Skip to content

Commit 792691d

Browse files
VizardsVizards
authored
fix(logger): diagnostics log visibility (#89)
1 parent 30dae47 commit 792691d

4 files changed

Lines changed: 105 additions & 22 deletions

File tree

‎src/logger.ts‎

Lines changed: 9 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -1,20 +1,16 @@
11
import vscode from 'vscode';
22

3-
let channel: vscode.OutputChannel | undefined;
3+
let channel: vscode.LogOutputChannel | undefined;
44

5-
function getChannel(): vscode.OutputChannel {
5+
function getChannel(): vscode.LogOutputChannel {
66
if (!channel) {
7-
channel = vscode.window.createOutputChannel('DeepSeek');
7+
channel = vscode.window.createOutputChannel('DeepSeek', { log: true });
88
}
99
return channel;
1010
}
1111

12-
function ts(): string {
13-
return new Date().toISOString().slice(11, 23);
14-
}
15-
16-
function write(level: string, args: unknown[]): void {
17-
const text = args
12+
function formatMessage(args: unknown[]): string {
13+
return args
1814
.map((a) => {
1915
if (typeof a === 'string') return a;
2016
if (a instanceof Error) return a.stack ?? a.message;
@@ -25,14 +21,13 @@ function write(level: string, args: unknown[]): void {
2521
}
2622
})
2723
.join(' ');
28-
getChannel().appendLine(`[${ts()}] [${level}] ${text}`);
2924
}
3025

3126
export const logger = {
32-
info: (...args: unknown[]) => write('info', args),
33-
warn: (...args: unknown[]) => write('warn', args),
34-
error: (...args: unknown[]) => write('error', args),
35-
debug: (...args: unknown[]) => write('debug', args),
27+
info: (...args: unknown[]) => getChannel().info(formatMessage(args)),
28+
warn: (...args: unknown[]) => getChannel().warn(formatMessage(args)),
29+
error: (...args: unknown[]) => getChannel().error(formatMessage(args)),
30+
debug: (...args: unknown[]) => getChannel().debug(formatMessage(args)),
3631
show: () => getChannel().show(),
3732
dispose: () => {
3833
channel?.dispose();

‎src/provider/diagnostics.ts‎

Lines changed: 60 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,8 @@ import { logger } from '../logger';
66
import type { DeepSeekMessage, DeepSeekRequest, DeepSeekTool, DeepSeekUsage } from '../types';
77
import { REPLAY_MARKER_MIME, parseFirstReplayMarker } from './replay';
88
import type { ConversationSegment } from './segment';
9+
import { ACTIVATE_TOOL_PREFIX } from './tools/consts';
10+
import type { ActivatePreflightInspection } from './tools/preflight';
911
import { IMAGE_DESCRIPTION_UNAVAILABLE } from './vision/consts';
1012
import type { VisionResolutionStats as VisionPipelineStats } from './vision/index';
1113

@@ -223,6 +225,57 @@ export function createCacheDiagnosticsRecorder(): CacheDiagnosticsRecorder {
223225
return new DefaultCacheDiagnosticsRecorder();
224226
}
225227

228+
export function logToolFlowDiagnostics({
229+
tools,
230+
messagesFiltered,
231+
preflight,
232+
activatePreflight,
233+
nextRound,
234+
initialResponseNotice,
235+
}: {
236+
tools: readonly vscode.LanguageModelChatTool[] | undefined;
237+
messagesFiltered: boolean;
238+
preflight: 'skipped' | 'handled' | 'ready' | 'round-limit';
239+
activatePreflight?: ActivatePreflightInspection;
240+
nextRound?: number;
241+
initialResponseNotice?: boolean;
242+
}): void {
243+
if (!getDebugLoggingEnabled()) {
244+
return;
245+
}
246+
247+
const activateToolCount =
248+
tools?.reduce(
249+
(count, tool) => count + (tool.name.startsWith(ACTIVATE_TOOL_PREFIX) ? 1 : 0),
250+
0,
251+
) ?? 0;
252+
if (preflight === 'skipped' && !messagesFiltered && activateToolCount === 0) {
253+
return;
254+
}
255+
256+
let message =
257+
`[tool-flow] preflight=${preflight}` +
258+
` tools=${tools?.length ?? 0}` +
259+
` activateTools=${activateToolCount}`;
260+
if (messagesFiltered) {
261+
message += ` messagesFiltered=true`;
262+
}
263+
if (activatePreflight) {
264+
message +=
265+
` preflightRounds=${activatePreflight.rounds}` +
266+
` calledActivators=${activatePreflight.calledActivatorNames.length}` +
267+
` remainingActivators=${activatePreflight.remainingActivatorNames.length}`;
268+
}
269+
if (nextRound !== undefined) {
270+
message += ` nextRound=${nextRound}`;
271+
}
272+
if (initialResponseNotice) {
273+
message += ` initialResponseNotice=true`;
274+
}
275+
276+
logger.info(message);
277+
}
278+
226279
interface VisionMessageStats {
227280
inputImageParts: number;
228281
inputImageMessages: number;
@@ -288,7 +341,6 @@ class DefaultCacheDiagnosticsRecorder implements CacheDiagnosticsRecorder {
288341
` thinking=${options.isThinkingModel}` +
289342
` thinkingEffort=${options.thinkingEffort}` +
290343
` maxTokens=${options.maxTokens ?? 'api-default'}` +
291-
` replayMarker=message-local` +
292344
` inputMessages=${options.inputMessages.length}` +
293345
` deepseekMessages=${options.request.messages.length}`,
294346
);
@@ -298,10 +350,15 @@ class DefaultCacheDiagnosticsRecorder implements CacheDiagnosticsRecorder {
298350
}
299351
const vscodeMessageTrace = formatVscodeMessageTrace(options.inputMessages);
300352
if (vscodeMessageTrace) {
301-
logger.info(`[cache-trace #${requestId}] vscodeMsgs ${vscodeMessageTrace}`);
353+
logger.debug(`[cache-trace #${requestId}] vscodeMsgs ${vscodeMessageTrace}`);
302354
}
303355
for (const detailLine of formatCacheTraceDetailLines(cacheTrace)) {
304-
logger.info(`[cache-trace #${requestId}] ${detailLine}`);
356+
const message = `[cache-trace #${requestId}] ${detailLine}`;
357+
if (detailLine.startsWith('contentMarkers ')) {
358+
logger.debug(message);
359+
} else {
360+
logger.info(message);
361+
}
305362
}
306363
const visionTrace = formatVisionTrace(visionResolution, options.visionStats);
307364
if (visionTrace) {

‎src/provider/dump.ts‎

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -907,15 +907,19 @@ function enqueueDumpWrite(label: string, write: () => Promise<void>): void {
907907
});
908908
}
909909

910+
function formatFileUri(fsPath: string): string {
911+
return vscode.Uri.file(fsPath).toString();
912+
}
913+
910914
function logProviderInputDump(
911915
options: DumpProviderInputOptions,
912916
paths: ProviderInputDumpPaths,
913917
toolSummary: ToolSummary,
914918
): void {
915919
const systemPromptSummary = summarizeVscodeSystemPrompt(options.messages);
916-
logger.info(
920+
logger.debug(
917921
`providerInputDump written: ${formatDumpSegment(options.segment)}` +
918-
` input=${paths.providerInput} ` +
922+
` input=${formatFileUri(paths.providerInput)} ` +
919923
`(${options.messages.length} msgs, ${toolSummary.toolCount} tools, ` +
920924
`activateTools=${toolSummary.activateToolCount}${formatActivateToolNames(
921925
toolSummary.activateToolNames,
@@ -932,10 +936,10 @@ function logRequestDump(
932936
requestJsonLength: number,
933937
): void {
934938
const systemPromptSummary = summarizeDeepSeekSystemPrompt(request.messages);
935-
logger.info(
939+
logger.debug(
936940
`requestDump written: ${formatDumpSegment(options.segment)}` +
937-
` request=${paths.request} ` +
938-
`input=${paths.input} resolved=${paths.resolved} ` +
941+
` request=${formatFileUri(paths.request)} ` +
942+
`input=${formatFileUri(paths.input)} resolved=${formatFileUri(paths.resolved)} ` +
939943
`(${request.messages.length} msgs, ${request.tools?.length ?? 0} tools, ` +
940944
`~${(requestJsonLength / 1024).toFixed(0)} KB) ` +
941945
formatHostSettingsSummary(summarizeHostSettings()) +

‎src/provider/tools/flow.ts‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import vscode from 'vscode';
22
import { t } from '../../i18n';
3+
import { logToolFlowDiagnostics } from '../diagnostics';
34
import { ACTIVATE_TOOL_PREFIX, MAX_PREFLIGHT_ROUNDS_PER_USER_REQUEST } from './consts';
45
import { createToolDriftNotice, filterProviderNotices } from './notices';
56
import {
@@ -28,8 +29,14 @@ export function processToolFlow({
2829
progress,
2930
}: ToolFlowOptions): ToolFlowResult {
3031
const filteredMessages = filterProviderNotices(filterPreflightControlFlow(messages));
32+
const messagesFiltered = filteredMessages !== messages;
3133

3234
if (!stabilizeToolList) {
35+
logToolFlowDiagnostics({
36+
tools,
37+
messagesFiltered,
38+
preflight: 'skipped',
39+
});
3340
return {
3441
preflightHandled: false,
3542
messages: filteredMessages,
@@ -39,12 +46,25 @@ export function processToolFlow({
3946
const activatePreflight = inspectActivatePreflight(messages, tools);
4047
if (activatePreflight.remainingActivatorNames.length > 0) {
4148
if (activatePreflight.rounds >= MAX_PREFLIGHT_ROUNDS_PER_USER_REQUEST) {
49+
logToolFlowDiagnostics({
50+
tools,
51+
messagesFiltered,
52+
preflight: 'round-limit',
53+
activatePreflight,
54+
});
4255
throw new Error(
4356
t('request.preflightRoundLimitExceeded', MAX_PREFLIGHT_ROUNDS_PER_USER_REQUEST),
4457
);
4558
}
4659

4760
const nextRound = activatePreflight.rounds + 1;
61+
logToolFlowDiagnostics({
62+
tools,
63+
messagesFiltered,
64+
preflight: 'handled',
65+
activatePreflight,
66+
nextRound,
67+
});
4868
for (const toolName of activatePreflight.remainingActivatorNames) {
4969
progress.report(
5070
new vscode.LanguageModelToolCallPart(
@@ -61,6 +81,13 @@ export function processToolFlow({
6181
const hasUnexpandedActivateTools =
6282
activatePreflight.rounds > 0 &&
6383
tools?.some((tool) => tool.name.startsWith(ACTIVATE_TOOL_PREFIX));
84+
logToolFlowDiagnostics({
85+
tools,
86+
messagesFiltered,
87+
preflight: 'ready',
88+
activatePreflight,
89+
initialResponseNotice: hasUnexpandedActivateTools,
90+
});
6491

6592
return {
6693
preflightHandled: false,

0 commit comments

Comments
 (0)