Skip to content

Commit 25f6d32

Browse files
committed
refactor(claude): improve telemetry logging and token calculation
add debug logging throughout telemetry pipeline for better observability update comments to clarify token calculation per Anthropic docs
1 parent 87c4392 commit 25f6d32

4 files changed

Lines changed: 71 additions & 10 deletions

File tree

src/cli/tui/routes/workflow/state/utils.ts

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -9,9 +9,9 @@ export function updateAgentTelemetryInList(
99
return agents.map((agent) => {
1010
if (agent.id !== agentId) return agent
1111

12-
// Context = input tokens (total)
13-
// Note: cached tokens are already INCLUDED in tokensIn, not separate
14-
// cached is just metadata showing how many of those tokens were served from cache
12+
// Per Anthropic docs: total_input = input_tokens + cache_read + cache_creation
13+
// tokensIn is pre-calculated as this total by the runner
14+
// cached is metadata showing how many tokens were served from/written to cache
1515
const currentContext = telemetry.tokensIn ?? 0
1616
const newTokensIn = currentContext > 0 ? currentContext : agent.telemetry.tokensIn
1717
const newTokensOut = telemetry.tokensOut ?? agent.telemetry.tokensOut
@@ -58,9 +58,9 @@ export function updateControllerTelemetry(
5858
controller: ControllerState,
5959
telemetry: Partial<AgentTelemetry>
6060
): ControllerState {
61-
// Context = input tokens (total)
62-
// Note: cached tokens are already INCLUDED in tokensIn, not separate
63-
// cached is just metadata showing how many of those tokens were served from cache
61+
// Per Anthropic docs: total_input = input_tokens + cache_read + cache_creation
62+
// tokensIn is pre-calculated as this total by the runner
63+
// cached is metadata showing how many tokens were served from/written to cache
6464
const currentContext = telemetry.tokensIn ?? 0
6565
const newTokensIn = currentContext > 0 ? currentContext : controller.telemetry.tokensIn
6666
const newTokensOut = telemetry.tokensOut ?? controller.telemetry.tokensOut

src/infra/engines/providers/claude/execution/runner.ts

Lines changed: 15 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import { metadata } from '../metadata.js';
77
import { expandHomeDir } from '../../../../../shared/utils/index.js';
88
import { ENV } from '../config.js';
99
import { createTelemetryCapture } from '../../../../../shared/telemetry/index.js';
10+
import { debug } from '../../../../../shared/logging/logger.js';
1011
import type { ParsedTelemetry } from '../../../core/types.js';
1112
import {
1213
formatThinking,
@@ -104,7 +105,8 @@ function formatStreamJsonLine(line: string): string[] | null {
104105
// Show status message when session starts
105106
return [formatStatus('Claude is analyzing your request...')];
106107
} else if (json.type === 'result') {
107-
// Calculate total input tokens (non-cached + cached)
108+
// Per Anthropic docs: total_input = input_tokens + cache_read + cache_creation
109+
// See: https://platform.claude.com/docs/en/build-with-claude/prompt-caching#tracking-cache-performance
108110
const cacheRead = json.usage.cache_read_input_tokens || 0;
109111
const cacheCreation = json.usage.cache_creation_input_tokens || 0;
110112
const totalCached = cacheRead + cacheCreation;
@@ -220,9 +222,19 @@ export async function runClaude(options: RunClaudeOptions): Promise<RunClaudeRes
220222
if (onTelemetry) {
221223
const captured = telemetryCapture.getCaptured();
222224
if (captured && captured.tokens) {
223-
// tokensIn should be TOTAL input tokens (non-cached + cached)
224-
// to match the log output format
225+
// Per Anthropic docs: total_input = input_tokens + cache_read + cache_creation
226+
// See: https://platform.claude.com/docs/en/build-with-claude/prompt-caching#tracking-cache-performance
225227
const totalIn = (captured.tokens.input ?? 0) + (captured.tokens.cached ?? 0);
228+
229+
debug('[TELEMETRY:2.5-RUNNER] [CLAUDE] Emitting telemetry via onTelemetry callback');
230+
debug('[TELEMETRY:2.5-RUNNER] [CLAUDE] CAPTURED: input=%d, output=%d, cached=%s',
231+
captured.tokens.input ?? 0,
232+
captured.tokens.output ?? 0,
233+
captured.tokens.cached ?? 'none');
234+
debug('[TELEMETRY:2.5-RUNNER] [CLAUDE] TOTAL CONTEXT: %d (input + cached), output=%d',
235+
totalIn,
236+
captured.tokens.output ?? 0);
237+
226238
onTelemetry({
227239
tokensIn: totalIn,
228240
tokensOut: captured.tokens.output ?? 0,

src/infra/engines/providers/claude/telemetryParser.ts

Lines changed: 20 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,5 @@
1+
import { debug } from '../../../../shared/logging/logger.js';
2+
13
interface CapturedTelemetry {
24
duration?: number;
35
cost?: number;
@@ -24,10 +26,18 @@ export function parseTelemetry(json: unknown): CapturedTelemetry | null {
2426
) {
2527
// eslint-disable-next-line @typescript-eslint/no-explicit-any
2628
const data = json as Record<string, any>;
29+
30+
debug('[TELEMETRY:1-PARSER] [CLAUDE] Received result event with usage data');
31+
debug('[TELEMETRY:1-PARSER] [CLAUDE] RAW: input_tokens=%d, output_tokens=%d, cache_read=%d, cache_creation=%d',
32+
data.usage.input_tokens,
33+
data.usage.output_tokens,
34+
data.usage.cache_read_input_tokens || 0,
35+
data.usage.cache_creation_input_tokens || 0);
36+
2737
// Calculate cached tokens from both cache_read_input_tokens and cache_creation_input_tokens
2838
const cachedTokens = (data.usage.cache_read_input_tokens || 0) + (data.usage.cache_creation_input_tokens || 0);
2939

30-
return {
40+
const result = {
3141
duration: data.duration_ms,
3242
cost: data.total_cost_usd,
3343
tokens: {
@@ -36,6 +46,15 @@ export function parseTelemetry(json: unknown): CapturedTelemetry | null {
3646
cached: cachedTokens > 0 ? cachedTokens : undefined,
3747
},
3848
};
49+
50+
debug('[TELEMETRY:1-PARSER] [CLAUDE] PARSED: input=%d, output=%d, cached=%s, duration=%dms, cost=$%s',
51+
result.tokens.input,
52+
result.tokens.output,
53+
result.tokens.cached ?? 'none',
54+
result.duration ?? 0,
55+
result.cost?.toFixed(6) ?? 'N/A');
56+
57+
return result;
3958
}
4059

4160
return null;

src/shared/telemetry/capture.ts

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import { logTelemetry } from './logger.js';
2+
import { debug } from '../logging/logger.js';
23
import type { EngineType } from '../../infra/engines/index.js';
34
import { parseTelemetry as parseClaudeTelemetry } from '../../infra/engines/providers/claude/telemetryParser.js';
45
import { parseTelemetry as parseCodexTelemetry } from '../../infra/engines/providers/codex/telemetryParser.js';
@@ -66,6 +67,14 @@ export function createTelemetryCapture(
6667
const parser = telemetryParsers[engine];
6768
const result = parser(json);
6869
if (result) {
70+
debug('[TELEMETRY:2-CAPTURE] [%s] Captured telemetry from stream', engine.toUpperCase());
71+
if (result.tokens) {
72+
debug('[TELEMETRY:2-CAPTURE] [%s] STORING: input=%d, output=%d, cached=%s',
73+
engine.toUpperCase(),
74+
result.tokens.input,
75+
result.tokens.output,
76+
result.tokens.cached ?? 'none');
77+
}
6978
captured = result;
7079
}
7180
} catch {
@@ -74,19 +83,40 @@ export function createTelemetryCapture(
7483
},
7584

7685
getCaptured(): CapturedTelemetry | null {
86+
if (captured) {
87+
debug('[TELEMETRY:2-CAPTURE] [%s] getCaptured() → input=%d, output=%d, cached=%s',
88+
engine.toUpperCase(),
89+
captured.tokens?.input ?? 0,
90+
captured.tokens?.output ?? 0,
91+
captured.tokens?.cached ?? 'none');
92+
}
7793
return captured;
7894
},
7995

8096
logCapturedTelemetry(exitCode: number): void {
97+
debug('[TELEMETRY:2-CAPTURE] [%s] logCapturedTelemetry called (exitCode=%d)', engine.toUpperCase(), exitCode);
98+
8199
if (!captured || !captured.tokens) {
100+
debug('[TELEMETRY:2-CAPTURE] [%s] SKIP: No captured telemetry or tokens', engine.toUpperCase());
82101
return;
83102
}
84103

85104
// Validate that token values are actual numbers
86105
if (typeof captured.tokens.input !== 'number' || typeof captured.tokens.output !== 'number') {
106+
debug('[TELEMETRY:2-CAPTURE] [%s] SKIP: Invalid token types (input=%s, output=%s)',
107+
engine.toUpperCase(),
108+
typeof captured.tokens.input,
109+
typeof captured.tokens.output);
87110
return;
88111
}
89112

113+
debug('[TELEMETRY:2-CAPTURE] [%s] LOGGING: input=%d, output=%d, cached=%s, cost=$%s',
114+
engine.toUpperCase(),
115+
captured.tokens.input,
116+
captured.tokens.output,
117+
captured.tokens.cached ?? 'none',
118+
captured.cost?.toFixed(6) ?? 'N/A');
119+
90120
logTelemetry({
91121
engine,
92122
model: model || 'default',

0 commit comments

Comments
 (0)