feat(telemetry): add span log correlation

Author: EhabY

src/api/authInterceptor.ts

@@ -83,8 +83,9 @@ export class AuthInterceptor implements vscode.Disposable {
 		hostname: string,
 	): Promise<unknown> {
 		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);

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),

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<T>(
 		eventName: string,
@@ -181,6 +181,21 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter {
 				`Telemetry span '${eventName}' ${op}('${name}') called after emit; mutation dropped`,
 			);
 		};
+		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 = {
 			traceId,
 			eventId,
@@ -189,9 +204,13 @@ export class TelemetryService implements vscode.Disposable, TelemetryReporter {
 				phaseName: string,
 				phaseFn: (childSpan: Span) => Promise<U>,
 				phaseProps: CallerProperties = {},
-				phaseMeasurements: Record<string, number> = {},
+				phaseMeasurements: CallerMeasurements = {},
 			): Promise<U> => {
-				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;
 	}

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<T>;
+	/** Emit a point-in-time log event correlated with this span. */
+	log(
+		logName: string,
+		properties?: CallerProperties,
+		measurements?: CallerMeasurements,
+	): void;
+	/** Emit a point-in-time error log event correlated with this span. */
+	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<T>(_phaseName: string, fn: (span: Span) => Promise<T>): Promise<T> {
 		return fn(NOOP_SPAN);
 	},
+	log: () => undefined,
+	logError: () => undefined,
 	markAborted: () => undefined,
 	markFailure: () => undefined,
 	setProperty: () => undefined,

src/telemetry/wireFormat.ts

@@ -32,7 +32,7 @@ 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 or correlated span event in the same trace. */
 	parentEventId: z.string().optional(),
 	error: z
 		.object({

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 correlated with 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();
+		});
 	});
 });

test/unit/telemetry/service.test.ts

@@ -91,6 +91,17 @@ describe("TelemetryService", () => {
 		});
 	});
 
+	it("leaves top-level logs uncorrelated", () => {
+		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,78 @@ describe("TelemetryService", () => {
 			});
 		});
 
+		it("span.log emits a correlated point-in-time event", 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 a correlated error log", 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");
+					childSpan.logError("oops", new Error("boom"));
+					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(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(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,15 +280,15 @@ 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());
 				await span.phase("p2", () => Promise.resolve());
 			});
 
 			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();
@@ -323,6 +406,35 @@ describe("TelemetryService", () => {
 			);
 		});
 
+		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("markAborted flips result to 'aborted' on normal return", async () => {
 			await h.service.trace("op", (span) => {
 				span.markAborted();
@@ -456,12 +568,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 +691,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";
 			});