Skip to content

Commit 56f0596

Browse files
EhabYEhabY
authored
feat(telemetry): instrument auth recovery (#962)
Record local telemetry for the OAuth and 401-recovery paths so latency and failure modes show up alongside the rest of the local telemetry stream. Auth events (src/instrumentation/auth.ts): - `auth.token_refreshed`: OAuth refresh attempt with `trigger` (`background` / `reactive`). - `auth.token_refresh.deduped`: emitted when a refresh call joins an in-flight refresh so the dropped trigger stays countable. - `auth.unauthorized_intercepted`: recovery path for a 401, with `recovery` (`refresh_success` / `login_required` / `none`) and `refreshAttempted`. - `auth.login_prompted`: modal login prompt outcome, with `trigger` and a `reason` on abort/failure. Shared telemetry plumbing picks up a `measurements` argument on `TelemetryService.trace`, span outcome helpers (`markFailure` / `markAborted`), and typed properties on `Span`. The SSH and WebSocket instrumentation modules migrate to the typed property API. Test helpers add `enableLocalTelemetry`, `TestSink.expectOne`, and `createMockServiceContainer`. First of two stacked PRs replacing #948. Closes part of #906; the workspace half lands in #963.
1 parent 99f304b commit 56f0596

24 files changed

Lines changed: 834 additions & 259 deletions

‎CHANGELOG.md‎

Lines changed: 10 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -13,20 +13,18 @@
1313
machine only and never sent anywhere. Configure via the new
1414
`coder.telemetry.level` setting (`local` by default, `off` to disable);
1515
see `coder.telemetry.local` for tunables.
16-
- Every `coder.*` command now records a `command.invoked` telemetry event with
17-
its duration and outcome, so command latency and failures are captured
18-
alongside other local telemetry.
19-
- Extension activation, remote workspace setup phases (auth retrieval,
20-
workspace lookup, workspace and agent readiness, SSH config write), and CLI
21-
binary download/verify now emit local telemetry events with their duration
22-
and outcome, so startup latency and failures are captured alongside other
23-
local telemetry.
16+
- Local telemetry now records `command.invoked` for each `coder.*` command
17+
with duration and outcome.
18+
- Local telemetry now records extension activation, remote workspace setup
19+
phases (auth retrieval, workspace lookup, workspace and agent readiness,
20+
SSH config write), and CLI binary download/verify with their durations
21+
and outcomes.
2422
- Local telemetry now records `http.requests` rollups for per-route HTTP
25-
health without emitting one event per request.
26-
- Connection lifecycle now records local telemetry: SSH process
23+
health, without emitting one event per request.
24+
- Local telemetry now records connection lifecycle: SSH process
2725
discovery/loss/recovery with sampled network info, and reconnecting
28-
WebSocket open, drop, reconnect, and state transitions, so connection
29-
stability is captured alongside other local telemetry.
26+
WebSocket open/drop/reconnect/state transitions.
27+
- Local telemetry now records authentication refresh and recovery prompts.
3028

3129
### Fixed
3230

‎src/api/authInterceptor.ts‎

Lines changed: 54 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,12 @@
11
import { type AxiosError, isAxiosError } from "axios";
22

3+
import { AuthTelemetry } from "../instrumentation/auth";
34
import { OAuthError } from "../oauth/errors";
45
import { toSafeHost } from "../util";
56

67
import type * as vscode from "vscode";
78

9+
import type { ServiceContainer } from "../core/container";
810
import type { SecretsManager } from "../core/secretsManager";
911
import type { Logger } from "../logging/logger";
1012
import type { RequestConfigWithMeta } from "../logging/types";
@@ -28,15 +30,20 @@ export type AuthRequiredHandler = (hostname: string) => Promise<boolean>;
2830
*/
2931
export class AuthInterceptor implements vscode.Disposable {
3032
private readonly interceptorId: number;
33+
private readonly authTelemetry: AuthTelemetry;
34+
private readonly logger: Logger;
35+
private readonly secretsManager: SecretsManager;
3136
private authRequiredPromise: Promise<boolean> | null = null;
3237

3338
constructor(
3439
private readonly client: CoderApi,
35-
private readonly logger: Logger,
3640
private readonly oauthSessionManager: OAuthSessionManager,
37-
private readonly secretsManager: SecretsManager,
41+
container: ServiceContainer,
3842
private readonly onAuthRequired?: AuthRequiredHandler,
3943
) {
44+
this.logger = container.getLogger();
45+
this.secretsManager = container.getSecretsManager();
46+
this.authTelemetry = new AuthTelemetry(container.getTelemetryService());
4047
this.interceptorId = this.client
4148
.getAxiosInstance()
4249
.interceptors.response.use(
@@ -68,47 +75,63 @@ export class AuthInterceptor implements vscode.Disposable {
6875
}
6976
const hostname = toSafeHost(baseUrl);
7077

71-
return this.handle401Error(error, hostname);
78+
return this.recoverFromUnauthorized(error, hostname);
7279
}
7380

74-
private async handle401Error(
81+
private recoverFromUnauthorized(
7582
error: AxiosError,
7683
hostname: string,
7784
): Promise<unknown> {
7885
this.logger.debug("Received 401 response, attempting recovery");
79-
80-
if (await this.oauthSessionManager.isLoggedInWithOAuth(hostname)) {
81-
try {
82-
const newTokens = await this.oauthSessionManager.refreshToken();
83-
this.client.setSessionToken(newTokens.access_token);
84-
this.logger.debug("Token refresh successful, retrying request");
85-
return this.retryRequest(error, newTokens.access_token);
86-
} catch (refreshError) {
87-
if (refreshError instanceof OAuthError) {
88-
const msg = `Token refresh failed: ${refreshError.message}`;
89-
if (refreshError.requiresReAuth) {
90-
this.logger.warn(msg);
91-
} else {
92-
this.logger.error(msg);
93-
}
94-
} else {
95-
this.logger.error("Token refresh failed:", refreshError);
86+
// TODO(#925): emit a correlated received-log here once Span.log() lands.
87+
return this.authTelemetry.traceAuthRecovery(async (recorder) => {
88+
// 1) OAuth refresh path.
89+
const isOAuth =
90+
await this.oauthSessionManager.isLoggedInWithOAuth(hostname);
91+
recorder.setRefreshAttempted(isOAuth);
92+
if (isOAuth) {
93+
const newToken = await this.tryOAuthRefresh();
94+
if (newToken) {
95+
recorder.setRecovery("refresh_success");
96+
return this.retryRequest(error, newToken);
9697
}
9798
}
98-
}
9999

100-
if (this.onAuthRequired) {
100+
// 2) Interactive re-auth fallback.
101+
if (!this.onAuthRequired) {
102+
recorder.setRecovery("none");
103+
throw error;
104+
}
105+
recorder.setRecovery("login_required");
101106
const success = await this.executeAuthRequired(hostname);
102-
if (success) {
103-
const auth = await this.secretsManager.getSessionAuth(hostname);
104-
if (auth) {
105-
this.logger.debug("Re-authentication successful, retrying request");
106-
return this.retryRequest(error, auth.token);
107-
}
107+
const auth = success
108+
? await this.secretsManager.getSessionAuth(hostname)
109+
: undefined;
110+
if (!auth) {
111+
throw error;
108112
}
109-
}
113+
this.logger.debug("Re-authentication successful, retrying request");
114+
return this.retryRequest(error, auth.token);
115+
});
116+
}
110117

111-
throw error;
118+
/** Returns the new access token on success, or undefined when refresh fails. */
119+
private async tryOAuthRefresh(): Promise<string | undefined> {
120+
try {
121+
const newTokens = await this.oauthSessionManager.refreshToken();
122+
this.client.setSessionToken(newTokens.access_token);
123+
this.logger.debug("Token refresh successful");
124+
return newTokens.access_token;
125+
} catch (refreshError) {
126+
if (!(refreshError instanceof OAuthError)) {
127+
this.logger.error("Token refresh failed:", refreshError);
128+
} else if (refreshError.requiresReAuth) {
129+
this.logger.warn(`Token refresh failed: ${refreshError.message}`);
130+
} else {
131+
this.logger.error(`Token refresh failed: ${refreshError.message}`);
132+
}
133+
return undefined;
134+
}
112135
}
113136

114137
/**

‎src/core/container.ts‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import * as vscode from "vscode";
22

33
import { CoderApi } from "../api/coderApi";
4+
import { AuthTelemetry } from "../instrumentation/auth";
45
import { LoginCoordinator } from "../login/loginCoordinator";
56
import { OAuthCallback } from "../oauth/oauthCallback";
67
import { buildSession, extractExtensionVersion } from "../telemetry/event";
@@ -103,6 +104,7 @@ export class ServiceContainer implements vscode.Disposable {
103104
this.mementoManager,
104105
this.logger,
105106
this.cliCredentialManager,
107+
new AuthTelemetry(this.telemetryService),
106108
this.oauthCallback,
107109
context.extension.id,
108110
);

‎src/extension.ts‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -145,9 +145,8 @@ async function doActivate(
145145
// Handles 401 responses (OAuth and otherwise)
146146
const authInterceptor = new AuthInterceptor(
147147
client,
148-
output,
149148
oauthSessionManager,
150-
secretsManager,
149+
serviceContainer,
151150
async () => {
152151
await handleAuthFailure();
153152
return false;

‎src/instrumentation/auth.ts‎

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,81 @@
1+
import type { TelemetryReporter } from "../telemetry/reporter";
2+
3+
export type AuthTokenRefreshTrigger = "background" | "reactive";
4+
export type AuthRecoveryAction = "refresh_success" | "login_required" | "none";
5+
export type AuthLoginPromptTrigger = "auth_required" | "missing_session";
6+
7+
export type LoginPromptReason =
8+
| "user_dismissed"
9+
| "no_url_provided"
10+
| "auth_failed";
11+
12+
export type LoginPromptOutcome =
13+
| { success: true }
14+
| { success: false; reason: LoginPromptReason };
15+
16+
interface AuthRecoveryRecorder {
17+
setRecovery(recovery: AuthRecoveryAction): void;
18+
setRefreshAttempted(attempted: boolean): void;
19+
}
20+
21+
export class AuthTelemetry {
22+
public constructor(private readonly telemetry: TelemetryReporter) {}
23+
24+
public traceTokenRefresh<T>(
25+
trigger: AuthTokenRefreshTrigger,
26+
fn: () => Promise<T>,
27+
): Promise<T> {
28+
return this.telemetry.trace("auth.token_refreshed", fn, { trigger });
29+
}
30+
31+
/** Logged when a refresh call joins an in-flight refresh and emits no span of its own. */
32+
public logTokenRefreshDeduped(trigger: AuthTokenRefreshTrigger): void {
33+
this.telemetry.log("auth.token_refresh.deduped", { trigger });
34+
}
35+
36+
/**
37+
* Wraps the auth-recovery path triggered by a 401. Initial properties
38+
* cover the throw-before-callback case.
39+
*/
40+
public traceAuthRecovery<T>(
41+
fn: (recorder: AuthRecoveryRecorder) => Promise<T>,
42+
): Promise<T> {
43+
return this.telemetry.trace(
44+
"auth.unauthorized_intercepted",
45+
(span) =>
46+
fn({
47+
setRecovery: (recovery) => span.setProperty("recovery", recovery),
48+
setRefreshAttempted: (attempted) =>
49+
span.setProperty("refreshAttempted", attempted),
50+
}),
51+
{ recovery: "none", refreshAttempted: false },
52+
);
53+
}
54+
55+
/**
56+
* Records `auth.login_prompted`. `auth_failed` marks the span as failure;
57+
* other non-success reasons mark it as aborted. The reason is copied to the
58+
* span's `reason` property on failure/abort only.
59+
*/
60+
public traceLoginPrompt<T extends LoginPromptOutcome>(
61+
trigger: AuthLoginPromptTrigger,
62+
fn: () => Promise<T>,
63+
): Promise<T> {
64+
return this.telemetry.trace(
65+
"auth.login_prompted",
66+
async (span) => {
67+
const result = await fn();
68+
if (!result.success) {
69+
span.setProperty("reason", result.reason);
70+
if (result.reason === "auth_failed") {
71+
span.markFailure();
72+
} else {
73+
span.markAborted();
74+
}
75+
}
76+
return result;
77+
},
78+
{ trigger },
79+
);
80+
}
81+
}

‎src/instrumentation/ssh.ts‎

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ export class SshTelemetry {
3434
): Promise<number | undefined> {
3535
return this.#telemetry.trace("ssh.process.discovered", async (span) => {
3636
const { pid, attempts } = await fn();
37-
span.setProperty("found", String(pid !== undefined));
37+
span.setProperty("found", pid !== undefined);
3838
span.setMeasurement("attempts", attempts);
3939
return pid;
4040
});
@@ -79,7 +79,6 @@ export class SshTelemetry {
7979
public processReplaced(): void {
8080
const now = performance.now();
8181
if (this.#processStartedAtMs !== undefined) {
82-
const wasLost = this.#processLostAtMs !== undefined;
8382
const measurements: Record<string, number> = {
8483
previousUptimeMs: now - this.#processStartedAtMs,
8584
};
@@ -88,7 +87,7 @@ export class SshTelemetry {
8887
}
8988
this.#telemetry.log(
9089
"ssh.process.replaced",
91-
{ wasLost: String(wasLost) },
90+
{ wasLost: this.#processLostAtMs !== undefined },
9291
measurements,
9392
);
9493
}
@@ -104,10 +103,9 @@ export class SshTelemetry {
104103
return;
105104
}
106105
const now = performance.now();
107-
const wasLost = this.#processLostAtMs !== undefined;
108106
this.#telemetry.log(
109107
"ssh.process.disposed",
110-
{ wasLost: String(wasLost) },
108+
{ wasLost: this.#processLostAtMs !== undefined },
111109
{ uptimeMs: now - this.#processStartedAtMs },
112110
);
113111
this.#processStartedAtMs = undefined;
@@ -131,7 +129,7 @@ export class SshTelemetry {
131129
this.#telemetry.log(
132130
"ssh.network.sampled",
133131
{
134-
p2p: String(network.p2p),
132+
p2p: network.p2p,
135133
preferredDerp: network.preferred_derp,
136134
},
137135
{

‎src/instrumentation/websocket.ts‎

Lines changed: 6 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -49,7 +49,6 @@ export class WebSocketTelemetry {
4949
readonly #telemetry: TelemetryReporter;
5050
#connectStartedAtMs: number | undefined;
5151
#connectionOpenedAtMs: number | undefined;
52-
#connectionDropEmitted = false;
5352
#reconnectCycle: ReconnectCycle | undefined;
5453

5554
public constructor(telemetry: TelemetryReporter) {
@@ -80,7 +79,6 @@ export class WebSocketTelemetry {
8079
const now = performance.now();
8180
const start = this.#connectStartedAtMs ?? now;
8281
this.#connectionOpenedAtMs = now;
83-
this.#connectionDropEmitted = false;
8482
this.#connectStartedAtMs = undefined;
8583
this.#telemetry.log(
8684
"connection.opened",
@@ -95,19 +93,19 @@ export class WebSocketTelemetry {
9593
closeCode?: number,
9694
error?: unknown,
9795
): void {
98-
if (
99-
this.#connectionOpenedAtMs === undefined ||
100-
this.#connectionDropEmitted
101-
) {
96+
// Capture-and-clear up-front so a throw, future await, or re-entry can't re-emit.
97+
const openedAtMs = this.#connectionOpenedAtMs;
98+
if (openedAtMs === undefined) {
10299
return;
103100
}
101+
this.#connectionOpenedAtMs = undefined;
104102

105103
const properties: CallerProperties = { cause };
106104
if (closeCode !== undefined) {
107-
properties.closeCode = String(closeCode);
105+
properties.closeCode = closeCode;
108106
}
109107
const measurements = {
110-
connectionDurationMs: performance.now() - this.#connectionOpenedAtMs,
108+
connectionDurationMs: performance.now() - openedAtMs,
111109
};
112110
if (error === undefined) {
113111
this.#telemetry.log("connection.dropped", properties, measurements);
@@ -119,13 +117,11 @@ export class WebSocketTelemetry {
119117
measurements,
120118
);
121119
}
122-
this.#connectionDropEmitted = true;
123120
}
124121

125122
public reset(): void {
126123
this.#connectStartedAtMs = undefined;
127124
this.#connectionOpenedAtMs = undefined;
128-
this.#connectionDropEmitted = false;
129125
this.#reconnectCycle = undefined;
130126
}
131127

0 commit comments

Comments
 (0)