Skip to content

Commit 3ec8c44

Browse files
committed
Prevent fallback failure source misattribution
1 parent 36521a7 commit 3ec8c44

6 files changed

Lines changed: 134 additions & 48 deletions

File tree

docs/TELEMETRY.md

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -167,9 +167,13 @@ completed message run discards it. `inference.done` settles success and only
167167
then applies successful-generation sampling. A failed `message.run.ended`
168168
settles an unresolved turn once as an unsampled terminal failure. Attribution
169169
uses the latest `inference.usage` source, the first lifecycle payload carrying
170-
the runtime-resolved provider/model pair for an attempt; it does not infer
171-
fallback from the externally selected source. Therefore a parent turn emits at
172-
most one terminal `$ai_generation`, including retry and failover paths.
170+
the runtime-resolved provider/model pair for an attempt. Each `inference.start`
171+
clears that authoritative source and records the newly attempted model. If a
172+
fallback fails before usage exposes its source, telemetry retains that actual
173+
model but uses the fixed `unknown` provider/source bucket rather than attributing
174+
it to the previously selected provider. When the attempted model still matches
175+
the selected source, that full source remains valid. Therefore a parent turn
176+
emits at most one terminal `$ai_generation`, including retry and failover paths.
173177

174178
## What's never collected
175179

src/session/run-sink.test.ts

Lines changed: 86 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,42 @@ const enabledHook: LifecycleHookStatus = {
2525
enabled: true,
2626
};
2727

28+
function attributionHarness(selectedSource = { provider: "provider-a", model: "model-a" }) {
29+
const captured: { event: string; properties: Record<string, unknown> }[] = [];
30+
const telemetry: Telemetry = {
31+
enabled: true,
32+
installationId: "test",
33+
capture: (capturedEvent, properties = {}) => {
34+
captured.push({ event: capturedEvent, properties });
35+
},
36+
captureIntentional: () => false,
37+
flush: async () => {},
38+
discard: () => {},
39+
};
40+
const observer = createTurnObserver({
41+
telemetry: () => telemetry,
42+
getSessionId: () => "session-1",
43+
getSource: () => selectedSource,
44+
});
45+
const runSink = createRunSink({
46+
emitter: new EventEmitter(),
47+
hookManager: stubHookManager([]),
48+
...observer,
49+
});
50+
return { captured, runSink };
51+
}
52+
53+
function failMessageRun(runSink: ReturnType<typeof createRunSink>): void {
54+
runSink.sink(event("inference.error", { error: { message: "attempt failed" } }));
55+
runSink.sink(
56+
event("message.run.ended", {
57+
messageRunId: "run-1",
58+
messageId: "message-1",
59+
status: "failed",
60+
}),
61+
);
62+
}
63+
2864
describe("createRunSink", () => {
2965
test("allocates no turn collector when no lifecycle hooks are configured", () => {
3066
const runSink = createRunSink({
@@ -138,52 +174,72 @@ describe("createRunSink", () => {
138174
expect(failures).toEqual([{ turnIndex: 0, error: "429 rate limit" }]);
139175
});
140176

141-
test("attributes terminal retry failure to the latest attempted source", () => {
142-
const captured: { event: string; properties: Record<string, unknown> }[] = [];
143-
const telemetry: Telemetry = {
144-
enabled: true,
145-
installationId: "test",
146-
capture: (capturedEvent, properties = {}) => {
147-
captured.push({ event: capturedEvent, properties });
148-
},
149-
captureIntentional: () => false,
150-
flush: async () => {},
151-
discard: () => {},
152-
};
153-
const selectedSource = { provider: "provider-a", model: "model-a" };
154-
const observer = createTurnObserver({
155-
telemetry: () => telemetry,
156-
getSessionId: () => "session-1",
157-
getSource: () => selectedSource,
158-
});
159-
const runSink = createRunSink({
160-
emitter: new EventEmitter(),
161-
hookManager: stubHookManager([]),
162-
...observer,
177+
test("uses unknown attribution when a fallback model fails before usage", () => {
178+
const { captured, runSink } = attributionHarness();
179+
180+
runSink.sink(event("inference.start", { model: "model-b" }));
181+
failMessageRun(runSink);
182+
183+
expect(captured).toHaveLength(1);
184+
expect(captured[0]?.event).toBe("$ai_generation");
185+
expect(captured[0]?.properties).toMatchObject({
186+
$ai_provider: "unknown",
187+
$ai_model: "model-b",
188+
$ai_is_error: true,
163189
});
190+
});
191+
192+
test("uses the selected source when its model fails before usage", () => {
193+
const { captured, runSink } = attributionHarness();
164194

165195
runSink.sink(event("inference.start", { model: "model-a" }));
166-
runSink.sink(event("inference.error", { error: { message: "attempt a failed" } }));
196+
failMessageRun(runSink);
197+
198+
expect(captured).toHaveLength(1);
199+
expect(captured[0]?.properties).toMatchObject({
200+
$ai_provider: "provider-a",
201+
$ai_model: "model-a",
202+
$ai_is_error: true,
203+
});
204+
});
205+
206+
test("uses authoritative usage attribution for a failed fallback", () => {
207+
const { captured, runSink } = attributionHarness();
208+
167209
runSink.sink(event("inference.start", { model: "model-b" }));
168210
runSink.sink(
169211
event("inference.usage", {
170212
usage: { input: 0, output: 0, cacheRead: 0, cacheWrite: 0, thinking: 0 },
171213
source: { sourceId: "fallback", provider: "provider-b", model: "model-b" },
172214
}),
173215
);
174-
runSink.sink(event("inference.error", { error: { message: "attempt b failed" } }));
216+
failMessageRun(runSink);
217+
218+
expect(captured).toHaveLength(1);
219+
expect(captured[0]?.properties).toMatchObject({
220+
$ai_provider: "provider-b",
221+
$ai_model: "model-b",
222+
$ai_is_error: true,
223+
});
224+
});
225+
226+
test("does not leak authoritative source attribution across retry attempts", () => {
227+
const { captured, runSink } = attributionHarness();
228+
229+
runSink.sink(event("inference.start", { model: "model-a" }));
175230
runSink.sink(
176-
event("message.run.ended", {
177-
messageRunId: "run-1",
178-
messageId: "message-1",
179-
status: "failed",
231+
event("inference.usage", {
232+
usage: { input: 0, output: 0, cacheRead: 0, cacheWrite: 0, thinking: 0 },
233+
source: { sourceId: "selected", provider: "provider-a", model: "model-a" },
180234
}),
181235
);
236+
runSink.sink(event("inference.error", { error: { message: "retry" } }));
237+
runSink.sink(event("inference.start", { model: "model-b" }));
238+
failMessageRun(runSink);
182239

183240
expect(captured).toHaveLength(1);
184-
expect(captured[0]?.event).toBe("$ai_generation");
185241
expect(captured[0]?.properties).toMatchObject({
186-
$ai_provider: "provider-b",
242+
$ai_provider: "unknown",
187243
$ai_model: "model-b",
188244
$ai_is_error: true,
189245
});

src/session/run-sink.ts

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -22,10 +22,9 @@ export interface RunSinkArgs {
2222
// run goes wrong. The turn index is the collector's current count: the
2323
// in-flight turn is the one that would have been recorded next.
2424
onTurnFailed?: (info: { turnIndex: number; error: string }) => void;
25-
// Fired when inference for a turn begins. The turn index is the collector's
26-
// current count (the in-flight turn that has not completed yet) — used to
27-
// stamp parent_trace_id on subagent_end while tools still run.
28-
onTurnStarted?: (info: { turnIndex: number }) => void;
25+
// Fired for every inference attempt. The model comes from inference.start,
26+
// while the turn index is the collector's current in-flight turn count.
27+
onTurnStarted?: (info: { turnIndex: number; model: string }) => void;
2928
// inference.usage is the first attempt event carrying the runtime-resolved
3029
// provider/model pair. It remains authoritative even when the selected source
3130
// outside the reactor has not changed during fallback.
@@ -150,7 +149,7 @@ export function createRunSink(args: RunSinkArgs): RunSink {
150149
perfObserver.observe(event);
151150
if (event.type === "inference.start") {
152151
turnInFlight = true;
153-
onTurnStarted?.({ turnIndex: turnCollector.getTurnCount() });
152+
onTurnStarted?.({ turnIndex: turnCollector.getTurnCount(), model: event.data.model });
154153
}
155154
if (event.type === "inference.usage") {
156155
onTurnSourceObserved?.({

src/telemetry/ai-observability.test.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -249,7 +249,7 @@ describe("createTurnObserver", () => {
249249
getSource: () => ({ provider: "openai-compatible", model: "model-x" }),
250250
});
251251

252-
observer.onTurnStarted({ turnIndex: 2 });
252+
observer.onTurnStarted({ turnIndex: 2, model: "model-x" });
253253
expect(getCurrentTurnTraceId()).toBe(`${SESSION_ID}:turn:2`);
254254
observer.onTurnComplete(fakeTurnContext({ turnIndex: 2, toolCalls: [], toolResults: [] }));
255255
expect(getCurrentTurnTraceId()).toBeUndefined();

src/telemetry/ai-observability.ts

Lines changed: 35 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -219,39 +219,65 @@ export interface CreateTurnObserverOptions {
219219
// session id in this same process, and a trace id built from a captured
220220
// one would file the new session's turns under the old session's traces.
221221
getSessionId: () => string;
222-
// The source the next inference will run against, which is the best
223-
// available attribution for a turn that failed before producing one.
222+
// The currently selected source. It is safe failure attribution only when
223+
// its model matches the model named by the latest inference.start.
224224
getSource: () => TurnSource;
225225
}
226226

227-
// Binds the emitters to the live session and source, giving the run sink two
228-
// plain callbacks and keeping the "read it now, do not capture it" rule in
229-
// one place instead of at each call site.
227+
const UNKNOWN_INFERENCE_PROVIDER = "unknown";
228+
229+
function failedAttemptSource(
230+
attemptedModel: string | undefined,
231+
observedSource: TurnSource | undefined,
232+
selectedSource: TurnSource,
233+
): TurnSource {
234+
if (observedSource !== undefined) return observedSource;
235+
if (attemptedModel === undefined || attemptedModel === selectedSource.model) {
236+
return selectedSource;
237+
}
238+
return { provider: UNKNOWN_INFERENCE_PROVIDER, model: attemptedModel };
239+
}
240+
241+
// Binds the emitters to the live session and source, keeping the "read it now,
242+
// do not capture it" rule in one place instead of at each call site.
230243
export function createTurnObserver(options: CreateTurnObserverOptions): {
231-
onTurnStarted: (info: { turnIndex: number }) => void;
244+
onTurnStarted: (info: { turnIndex: number; model: string }) => void;
232245
onTurnSourceObserved: (info: { turnIndex: number; source: TurnSource }) => void;
233246
onTurnComplete: (ctx: TurnContext) => void;
234247
onTurnFailed: (info: { turnIndex: number; error: string }) => void;
235248
} {
249+
let latestAttemptModel: string | undefined;
236250
let latestAttemptSource: TurnSource | undefined;
251+
252+
function clearAttempt(): void {
253+
latestAttemptModel = undefined;
254+
latestAttemptSource = undefined;
255+
}
256+
237257
return {
238258
onTurnStarted: (info) => {
259+
latestAttemptModel = info.model;
260+
latestAttemptSource = undefined;
239261
noteCurrentTurnTraceId(turnTraceId(options.getSessionId(), info.turnIndex));
240262
},
241263
onTurnSourceObserved: (info) => {
242264
latestAttemptSource = { ...info.source };
243265
},
244266
onTurnComplete: (ctx) => {
245-
latestAttemptSource = undefined;
267+
clearAttempt();
246268
clearCurrentTurnTraceId();
247269
emitAiObservability(options.telemetry(), ctx, {
248270
sessionId: options.getSessionId(),
249271
});
250272
},
251273
onTurnFailed: (info) => {
252274
clearCurrentTurnTraceId();
253-
const source = latestAttemptSource ?? options.getSource();
254-
latestAttemptSource = undefined;
275+
const source = failedAttemptSource(
276+
latestAttemptModel,
277+
latestAttemptSource,
278+
options.getSource(),
279+
);
280+
clearAttempt();
255281
emitAiTurnFailure(options.telemetry(), {
256282
sessionId: options.getSessionId(),
257283
source,

src/tui/runner.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1590,6 +1590,7 @@ export async function runTUI(initialConfig: Config): Promise<number> {
15901590
hookManager,
15911591
initialTurnCount: resumeSeed.turnsUsed,
15921592
onTurnStarted: turnObserver.onTurnStarted,
1593+
onTurnSourceObserved: turnObserver.onTurnSourceObserved,
15931594
onTurnComplete: turnObserver.onTurnComplete,
15941595
onTurnFailed: turnObserver.onTurnFailed,
15951596
// persistRunSnapshot is defined below but not invoked until the stream

0 commit comments

Comments
 (0)