diff --git a/src/api/authInterceptor.ts b/src/api/authInterceptor.ts index 9fc71148a..f943aa6a8 100644 --- a/src/api/authInterceptor.ts +++ b/src/api/authInterceptor.ts @@ -83,8 +83,9 @@ export class AuthInterceptor implements vscode.Disposable { hostname: string, ): Promise { this.logger.debug("Received 401 response, attempting recovery"); - // TODO(#925): emit a correlated received-log here once Span.log() lands. return this.authTelemetry.traceAuthRecovery(async (recorder) => { + recorder.logReceived(); + // 1) OAuth refresh path. const isOAuth = await this.oauthSessionManager.isLoggedInWithOAuth(hostname); diff --git a/src/instrumentation/auth.ts b/src/instrumentation/auth.ts index 15e8ffcfd..c6cba325c 100644 --- a/src/instrumentation/auth.ts +++ b/src/instrumentation/auth.ts @@ -14,6 +14,7 @@ export type LoginPromptOutcome = | { success: false; reason: LoginPromptReason }; interface AuthRecoveryRecorder { + logReceived(): void; setRecovery(recovery: AuthRecoveryAction): void; setRefreshAttempted(attempted: boolean): void; } @@ -44,6 +45,7 @@ export class AuthTelemetry { "auth.unauthorized_intercepted", (span) => fn({ + logReceived: () => span.log("received"), setRecovery: (recovery) => span.setProperty("recovery", recovery), setRefreshAttempted: (attempted) => span.setProperty("refreshAttempted", attempted), diff --git a/src/telemetry/service.ts b/src/telemetry/service.ts index 06b455896..aa65485cf 100644 --- a/src/telemetry/service.ts +++ b/src/telemetry/service.ts @@ -129,7 +129,7 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { * Run a timed operation. The emitted event carries `durationMs` and a * `result` of `success`, `error`, or `aborted` (set via `span.markAborted()` * for intentional early exits). All events from one call share a `traceId`; - * phase children carry `parentEventId`. + * child phases and span logs carry `parentEventId`. */ public trace( eventName: string, @@ -178,7 +178,22 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { let mark: "aborted" | "error" | undefined; const warnPostEmit = (op: string, name: string): void => { this.logger.warn( - `Telemetry span '${eventName}' ${op}('${name}') called after emit; mutation dropped`, + `Telemetry span '${eventName}' ${op}('${name}') called after emit; call ignored`, + ); + }; + const emitSpanLog = ( + logName: string, + logProperties: CallerProperties, + logMeasurements: CallerMeasurements, + error?: unknown, + ): void => { + const safeName = this.#sanitizeChildName(logName, "log"); + this.#safeEmit( + newSpanId(), + `${eventName}.${safeName}`, + stringifyProps(logProperties), + logMeasurements, + { traceId, parentEventId: eventId, traceLevel, error }, ); }; const span: Span = { @@ -189,9 +204,13 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { phaseName: string, phaseFn: (childSpan: Span) => Promise, phaseProps: CallerProperties = {}, - phaseMeasurements: Record = {}, + phaseMeasurements: CallerMeasurements = {}, ): Promise => { - const safeName = this.#sanitizePhaseName(phaseName); + if (completed) { + warnPostEmit("phase", phaseName); + return phaseFn(NOOP_SPAN); + } + const safeName = this.#sanitizeChildName(phaseName, "phase"); return this.#startSpan( `${eventName}.${safeName}`, phaseFn, @@ -200,6 +219,29 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { { traceId, parentEventId: eventId, traceLevel }, ); }, + log: ( + logName: string, + logProperties: CallerProperties = {}, + logMeasurements: CallerMeasurements = {}, + ): void => { + if (completed) { + warnPostEmit("log", logName); + return; + } + emitSpanLog(logName, logProperties, logMeasurements); + }, + logError: ( + logName: string, + error: unknown, + logProperties: CallerProperties = {}, + logMeasurements: CallerMeasurements = {}, + ): void => { + if (completed) { + warnPostEmit("logError", logName); + return; + } + emitSpanLog(logName, logProperties, logMeasurements, error); + }, setProperty(name: string, value: CallerPropertyValue): void { if (completed) { warnPostEmit("setProperty", name); @@ -243,13 +285,13 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter { }); } - #sanitizePhaseName(name: string): string { + #sanitizeChildName(name: string, kind: "phase" | "log"): string { if (!name.includes(".")) { return name; } const sanitized = name.replaceAll(".", "_"); this.logger.warn( - `Telemetry phase name '${name}' contains '.', sanitized to '${sanitized}'`, + `Telemetry ${kind} name '${name}' contains '.', sanitized to '${sanitized}'`, ); return sanitized; } diff --git a/src/telemetry/span.ts b/src/telemetry/span.ts index 06b69ca69..89d1284aa 100644 --- a/src/telemetry/span.ts +++ b/src/telemetry/span.ts @@ -7,8 +7,8 @@ import type { export type SpanResult = "success" | "aborted" | "error"; /** - * Parent span handle. Children's `eventName` composes as `${parent.eventName}.${phaseName}`. - * Phase names should not contain `.`; if they do, dots are replaced with `_` and a warning is logged. + * Parent span handle. Child phases and logs compose as `${parent.eventName}.${name}`. + * Child names should not contain `.`; if they do, dots are replaced with `_` and a warning is logged. * Recurse via `phase` for grandchildren. */ export interface Span { @@ -22,6 +22,19 @@ export interface Span { properties?: CallerProperties, measurements?: CallerMeasurements, ): Promise; + /** Emit a point-in-time log event under this span. No framework-set `result` or `durationMs`. */ + log( + logName: string, + properties?: CallerProperties, + measurements?: CallerMeasurements, + ): void; + /** Emit a point-in-time error log event under this span. No framework-set `result` or `durationMs`. */ + logError( + logName: string, + error: unknown, + properties?: CallerProperties, + measurements?: CallerMeasurements, + ): void; /** Add or replace a property on the event emitted for this span. */ setProperty(name: string, value: CallerPropertyValue): void; /** Add or replace a measurement on the event emitted for this span. */ @@ -40,6 +53,8 @@ export const NOOP_SPAN: Span = { phase(_phaseName: string, fn: (span: Span) => Promise): Promise { return fn(NOOP_SPAN); }, + log: () => undefined, + logError: () => undefined, markAborted: () => undefined, markFailure: () => undefined, setProperty: () => undefined, diff --git a/src/telemetry/wireFormat.ts b/src/telemetry/wireFormat.ts index 69b71dbfd..564598cbb 100644 --- a/src/telemetry/wireFormat.ts +++ b/src/telemetry/wireFormat.ts @@ -32,7 +32,11 @@ const TelemetryEventSchema = z.object({ measurements: z.record(z.string(), z.number()), /** Shared by all events in a trace. Maps to OTel `trace_id`. */ traceId: z.string().optional(), - /** Parent event in the same trace. Maps to OTel `parent_span_id`. */ + /** + * Parent span in the same trace. For phase children this maps to OTel + * `parent_span_id`. For span logs it maps to OTel `span_id` on the log + * record (the span the log belongs to). + */ parentEventId: z.string().optional(), error: z .object({ diff --git a/test/unit/api/authInterceptor.test.ts b/test/unit/api/authInterceptor.test.ts index b744030dd..719291209 100644 --- a/test/unit/api/authInterceptor.test.ts +++ b/test/unit/api/authInterceptor.test.ts @@ -562,5 +562,29 @@ describe("AuthInterceptor", () => { sink.expectOne("auth.unauthorized_intercepted").measurements.durationMs, ).toEqual(expect.any(Number)); }); + + it("emits a received log under the recovery span", async () => { + const sink = new TestSink(); + const ctx = createTestContext(); + await ctx.setupOAuthTokens(); + ctx.mockOAuthManager.refreshToken.mockResolvedValue( + createMockTokenResponse({ access_token: "new" }), + ); + vi.spyOn(ctx.axiosInstance, "request").mockResolvedValue({ + status: 200, + }); + ctx.createInterceptor(undefined, createTestTelemetryService(sink)); + + await ctx.axiosInstance.triggerResponseError( + createAxiosError(401, "Unauthorized"), + ); + + const received = sink.expectOne("auth.unauthorized_intercepted.received"); + const recovery = sink.expectOne("auth.unauthorized_intercepted"); + expect(received.traceId).toBe(recovery.traceId); + expect(received.parentEventId).toBe(recovery.eventId); + expect(received.measurements.durationMs).toBeUndefined(); + expect(received.properties.result).toBeUndefined(); + }); }); }); diff --git a/test/unit/telemetry/service.test.ts b/test/unit/telemetry/service.test.ts index ba0934175..45c7a2993 100644 --- a/test/unit/telemetry/service.test.ts +++ b/test/unit/telemetry/service.test.ts @@ -91,6 +91,17 @@ describe("TelemetryService", () => { }); }); + it("top-level log/logError emit no traceId or parentEventId", () => { + h.service.log("plain"); + h.service.logError("plain.error", new Error("nope")); + + const [log, logError] = h.sink.events; + expect(log.traceId).toBeUndefined(); + expect(log.parentEventId).toBeUndefined(); + expect(logError.traceId).toBeUndefined(); + expect(logError.parentEventId).toBeUndefined(); + }); + describe("trace", () => { it("returns the wrapped value and records durationMs on success", async () => { vi.useFakeTimers(); @@ -165,6 +176,87 @@ describe("TelemetryService", () => { }); }); + it("span.log emits with the span's traceId and parentEventId", async () => { + await h.service.trace("op", (span) => { + span.log("checkpoint", { ready: true }, { count: 1 }); + return Promise.resolve(); + }); + + const [log, parent] = h.sink.events; + expect(log).toMatchObject({ + eventName: "op.checkpoint", + properties: { ready: "true" }, + measurements: { count: 1 }, + }); + expect(log.eventId).not.toBe(parent.eventId); + expect(log.traceId).toBe(parent.traceId); + expect(log.parentEventId).toBe(parent.eventId); + expect(log.properties.result).toBeUndefined(); + expect(log.measurements.durationMs).toBeUndefined(); + }); + + it("span.logError emits with traceId, parentEventId, and the error block", async () => { + await h.service.trace("op", (span) => { + span.logError( + "failed", + new TypeError("nope"), + { attempt: 1 }, + { retries: 2 }, + ); + return Promise.resolve(); + }); + + const [log, parent] = h.sink.events; + expect(log).toMatchObject({ + eventName: "op.failed", + properties: { attempt: "1" }, + measurements: { retries: 2 }, + error: { message: "nope", type: "TypeError" }, + }); + expect(log.traceId).toBe(parent.traceId); + expect(log.parentEventId).toBe(parent.eventId); + expect(log.measurements.durationMs).toBeUndefined(); + }); + + it("child span logs point at the child span", async () => { + await h.service.trace("op", async (span) => { + await span.phase("phase", (childSpan) => { + childSpan.log("checkpoint", { ready: true }, { count: 1 }); + childSpan.logError( + "oops", + new Error("boom"), + { attempt: 2 }, + { retries: 3 }, + ); + return Promise.resolve(); + }); + }); + + const [log, logError, child, parent] = h.sink.events; + expect(log.eventName).toBe("op.phase.checkpoint"); + expect(log.traceId).toBe(parent.traceId); + expect(log.parentEventId).toBe(child.eventId); + expect(log.properties.ready).toBe("true"); + expect(log.measurements.count).toBe(1); + expect(logError.eventName).toBe("op.phase.oops"); + expect(logError.traceId).toBe(parent.traceId); + expect(logError.parentEventId).toBe(child.eventId); + expect(logError.error).toMatchObject({ message: "boom" }); + expect(logError.properties.attempt).toBe("2"); + expect(logError.measurements.retries).toBe(3); + expect(child.parentEventId).toBe(parent.eventId); + }); + + it("span log names containing '.' are sanitized like phase names", async () => { + await h.service.trace("op", (span) => { + span.log("bad.name"); + return Promise.resolve(); + }); + + const [log] = h.sink.events; + expect(log.eventName).toBe("op.bad_name"); + }); + it("flat traces (no phases) emit a single event with a fresh traceId", async () => { await h.service.trace("a", () => Promise.resolve(1)); await h.service.trace("b", () => Promise.resolve(2)); @@ -197,7 +289,7 @@ describe("TelemetryService", () => { expect(phase2.traceId).toBe(parent.traceId); }); - it("phase children carry parentEventId pointing at the parent's eventId; logs do not", async () => { + it("phase children carry parentEventId pointing at the parent's eventId; top-level logs do not", async () => { h.service.log("plain"); await h.service.trace("op", async (span) => { await span.phase("p1", () => Promise.resolve()); @@ -205,7 +297,7 @@ describe("TelemetryService", () => { }); const [plain, p1, p2, parent] = h.sink.events; - // log/logError/time events have no parentEventId field. + // Top-level log/logError events have no parentEventId field. expect(plain.parentEventId).toBeUndefined(); // Parent (root) has no parentEventId either. expect(parent.parentEventId).toBeUndefined(); @@ -287,7 +379,7 @@ describe("TelemetryService", () => { expect(phase.eventName).toBe("op.bad_name"); }); - it("warns and ignores setProperty/setMeasurement called after emit", async () => { + it("drops setProperty/setMeasurement/markAborted/markFailure called after emit", async () => { let escapedSpan: Span | undefined; await h.service.trace("op", (span) => { escapedSpan = span; @@ -295,32 +387,63 @@ describe("TelemetryService", () => { }); expect(h.sink.events).toHaveLength(1); - const warnBefore = vi.mocked(h.logger.warn).mock.calls.length; escapedSpan?.setProperty("late", "ignored"); escapedSpan?.setMeasurement("lateMs", 99); escapedSpan?.markAborted(); escapedSpan?.markFailure(); - // Mutations dropped: emitted event is unchanged. expect(h.sink.events[0].properties.late).toBeUndefined(); expect(h.sink.events[0].measurements.lateMs).toBeUndefined(); expect(h.sink.events[0].properties.result).toBe("success"); + }); - // Each post-emit mutation logs a warning. - expect(vi.mocked(h.logger.warn).mock.calls.length).toBe(warnBefore + 4); - expect(vi.mocked(h.logger.warn).mock.calls[warnBefore][0]).toContain( - "setProperty", - ); - expect(vi.mocked(h.logger.warn).mock.calls[warnBefore + 1][0]).toContain( - "setMeasurement", - ); - expect(vi.mocked(h.logger.warn).mock.calls[warnBefore + 2][0]).toContain( - "markAborted", - ); - expect(vi.mocked(h.logger.warn).mock.calls[warnBefore + 3][0]).toContain( - "markFailure", - ); + it("drops span logs called after emit", async () => { + let escapedSpan: Span | undefined; + await h.service.trace("op", (span) => { + escapedSpan = span; + return Promise.resolve(); + }); + + escapedSpan?.log("late"); + escapedSpan?.logError("late_error", new Error("ignored")); + + expect(h.sink.events).toHaveLength(1); + }); + + it("runs phase fns called after emit but emits no phase event", async () => { + let escapedSpan: Span | undefined; + await h.service.trace("op", (span) => { + escapedSpan = span; + return Promise.resolve(); + }); + + const result = await escapedSpan?.phase("late", (childSpan) => { + childSpan.log("ignored"); + return Promise.resolve("ran"); + }); + + expect(result).toBe("ran"); + expect(h.sink.events).toHaveLength(1); + }); + + it("warns once per post-emit method call", async () => { + let escapedSpan: Span | undefined; + await h.service.trace("op", (span) => { + escapedSpan = span; + return Promise.resolve(); + }); + + const warnBefore = vi.mocked(h.logger.warn).mock.calls.length; + escapedSpan?.setProperty("late", "ignored"); + escapedSpan?.setMeasurement("lateMs", 99); + escapedSpan?.markAborted(); + escapedSpan?.markFailure(); + escapedSpan?.log("late_log"); + escapedSpan?.logError("late_log_error", new Error("ignored")); + await escapedSpan?.phase("late_phase", () => Promise.resolve()); + + expect(vi.mocked(h.logger.warn).mock.calls.length).toBe(warnBefore + 7); }); it("markAborted flips result to 'aborted' on normal return", async () => { @@ -456,12 +579,20 @@ describe("TelemetryService", () => { h.service.log("a"); h.service.logError("b", new Error("ignored")); - expect(await h.service.trace("c", () => Promise.resolve(42))).toBe(42); + expect( + await h.service.trace("c", (span) => { + span.log("ignored"); + span.logError("ignored_error", new Error("ignored")); + return Promise.resolve(42); + }), + ).toBe(42); const traceResult = await h.service.trace("d", async (span) => { - const phaseValue = await span.phase("p", () => - Promise.resolve("inner"), - ); + const phaseValue = await span.phase("p", (childSpan) => { + childSpan.log("ignored"); + childSpan.logError("ignored_error", new Error("ignored")); + return Promise.resolve("inner"); + }); expect(phaseValue).toBe("inner"); return "outer"; }); @@ -571,9 +702,12 @@ describe("TelemetryService", () => { it("trace and span.phase complete normally when the sink throws", async () => { const service = makeService([throwingSink]); const result = await service.trace("op", async (span) => { - const phaseValue = await span.phase("p", () => - Promise.resolve("phase"), - ); + span.log("checkpoint"); + span.logError("failure", new Error("telemetry-error")); + const phaseValue = await span.phase("p", (childSpan) => { + childSpan.log("checkpoint"); + return Promise.resolve("phase"); + }); expect(phaseValue).toBe("phase"); return "trace"; });