feat(telemetry): add span log correlation

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,
@@ -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<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 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<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,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({

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