Skip to content

Commit e32ba50

Browse files
committed
Improve logging and isolate it into a separate file
1 parent cf230ff commit e32ba50

File tree

8 files changed

+215
-80
lines changed

8 files changed

+215
-80
lines changed

src/api.ts

Lines changed: 18 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
import { AxiosInstance, InternalAxiosRequestConfig, isAxiosError } from "axios";
1+
import { AxiosInstance } from "axios";
22
import { spawn } from "child_process";
33
import { Api } from "coder/site/src/api/api";
44
import { Workspace } from "coder/site/src/api/typesGenerated";
@@ -9,6 +9,13 @@ import { errToStr } from "./api-helper";
99
import { CertificateError } from "./error";
1010
import { FeatureSet } from "./featureSet";
1111
import { getGlobalFlags } from "./globalFlags";
12+
import {
13+
createRequestMeta,
14+
logRequestStart,
15+
logRequestSuccess,
16+
logRequestError,
17+
RequestConfigWithMeta,
18+
} from "./logging/netLog";
1219
import { getProxyForUrl } from "./proxy";
1320
import { Storage } from "./storage";
1421
import { expandPath } from "./util";
@@ -116,72 +123,33 @@ export function makeCoderSdk(
116123
return restClient;
117124
}
118125

119-
interface RequestConfigWithMetadata extends InternalAxiosRequestConfig {
120-
metadata?: {
121-
requestId: string;
122-
startedAt: number;
123-
};
124-
}
125-
126-
function addLoggingInterceptors(
126+
export function addLoggingInterceptors(
127127
client: AxiosInstance,
128128
logger: vscode.LogOutputChannel,
129129
) {
130130
client.interceptors.request.use(
131131
(config) => {
132-
const requestId = crypto.randomUUID().replace(/-/g, "");
133-
(config as RequestConfigWithMetadata).metadata = {
134-
requestId,
135-
startedAt: Date.now(),
136-
};
137-
138-
logger.trace(
139-
`req ${requestId}: ${config.method?.toUpperCase()} ${config.url}`,
140-
config.data ?? "",
141-
);
142-
132+
const meta = createRequestMeta();
133+
(config as RequestConfigWithMeta).metadata = meta;
134+
logRequestStart(logger, meta.requestId, config);
143135
return config;
144136
},
145137
(error: unknown) => {
146-
let message: string = "Request error";
147-
if (isAxiosError(error)) {
148-
const meta = (error.config as RequestConfigWithMetadata)?.metadata;
149-
const requestId = meta?.requestId ?? "n/a";
150-
message = `req ${requestId} error`;
151-
}
152-
logger.error(message, error);
153-
138+
logRequestError(logger, error);
154139
return Promise.reject(error);
155140
},
156141
);
157142

158143
client.interceptors.response.use(
159144
(response) => {
160-
const { requestId, startedAt } =
161-
(response.config as RequestConfigWithMetadata).metadata ?? {};
162-
const ms = startedAt ? Date.now() - startedAt : undefined;
163-
164-
logger.trace(
165-
`res ${requestId ?? "n/a"}: ${response.status}${
166-
ms !== undefined ? ` in ${ms}ms` : ""
167-
}`,
168-
// { responseBody: response.data }, // TODO too noisy
169-
);
145+
const meta = (response.config as RequestConfigWithMeta).metadata;
146+
if (meta) {
147+
logRequestSuccess(logger, meta, response);
148+
}
170149
return response;
171150
},
172151
(error: unknown) => {
173-
let message = "Response error";
174-
if (isAxiosError(error)) {
175-
const { metadata } = (error.config as RequestConfigWithMetadata) ?? {};
176-
const requestId = metadata?.requestId ?? "n/a";
177-
const startedAt = metadata?.startedAt;
178-
const ms = startedAt ? Date.now() - startedAt : undefined;
179-
180-
const status = error.response?.status ?? "unknown";
181-
message = `res ${requestId}: ${status}${ms !== undefined ? ` in ${ms}ms` : ""}`;
182-
}
183-
logger.error(message, error);
184-
152+
logRequestError(logger, error);
185153
return Promise.reject(error);
186154
},
187155
);

src/error.test.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ import https from "https";
44
import * as path from "path";
55
import { afterAll, beforeAll, it, expect, vi } from "vitest";
66
import { CertificateError, X509_ERR, X509_ERR_CODE } from "./error";
7-
import { Logger } from "./logger";
7+
import { Logger } from "./logging/logger";
88

99
// Before each test we make a request to sanity check that we really get the
1010
// error we are expecting, then we run it through CertificateError.

src/error.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@ import { isApiError, isApiErrorResponse } from "coder/site/src/api/errors";
33
import * as forge from "node-forge";
44
import * as tls from "tls";
55
import * as vscode from "vscode";
6-
import { Logger } from "./logger";
6+
import { Logger } from "./logging/logger";
77

88
// X509_ERR_CODE represents error codes as returned from BoringSSL/OpenSSL.
99
export enum X509_ERR_CODE {

src/headers.test.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import * as os from "os";
22
import { it, expect, describe, beforeEach, afterEach, vi } from "vitest";
33
import { WorkspaceConfiguration } from "vscode";
44
import { getHeaderCommand, getHeaders } from "./headers";
5-
import { Logger } from "./logger";
5+
import { Logger } from "./logging/logger";
66

77
const logger: Logger = {
88
trace: () => {},

src/headers.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import * as cp from "child_process";
22
import * as os from "os";
33
import * as util from "util";
44
import type { WorkspaceConfiguration } from "vscode";
5-
import { Logger } from "./logger";
5+
import { Logger } from "./logging/logger";
66
import { escapeCommandArg } from "./util";
77

88
interface ExecException {
File renamed without changes.

src/logging/netLog.ts

Lines changed: 176 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,176 @@
1+
import {
2+
type InternalAxiosRequestConfig,
3+
type AxiosResponse,
4+
type AxiosError,
5+
isAxiosError,
6+
} from "axios";
7+
import { Buffer } from "node:buffer";
8+
import crypto from "node:crypto";
9+
import type * as vscode from "vscode";
10+
import { errToStr } from "../api-helper";
11+
12+
export interface RequestMeta {
13+
requestId: string;
14+
startedAt: number;
15+
}
16+
17+
export type RequestConfigWithMeta = InternalAxiosRequestConfig & {
18+
metadata?: RequestMeta;
19+
};
20+
21+
function shortId(id: string): string {
22+
return id.slice(0, 8);
23+
}
24+
25+
function sizeOf(data: unknown): number {
26+
if (data === null || data === undefined) {
27+
return 0;
28+
}
29+
if (typeof data === "string") {
30+
return Buffer.byteLength(data);
31+
}
32+
if (Buffer.isBuffer(data)) {
33+
return data.length;
34+
}
35+
if (data instanceof ArrayBuffer || ArrayBuffer.isView(data)) {
36+
return data.byteLength;
37+
}
38+
if (
39+
typeof data === "object" &&
40+
"size" in data &&
41+
typeof data.size === "number"
42+
) {
43+
return data.size;
44+
}
45+
return 0;
46+
}
47+
48+
export function createRequestMeta(): RequestMeta {
49+
return {
50+
requestId: crypto.randomUUID().replace(/-/g, ""),
51+
startedAt: Date.now(),
52+
};
53+
}
54+
55+
export function logRequestStart(
56+
logger: vscode.LogOutputChannel,
57+
requestId: string,
58+
config: InternalAxiosRequestConfig,
59+
): void {
60+
const method = (config.method ?? "GET").toUpperCase();
61+
const url = config.url || "";
62+
const len = config.headers?.["content-length"] as string | undefined;
63+
const lenStr = len ? ` (${len}b)` : "";
64+
logger.trace(`→ ${shortId(requestId)} ${method} ${url}${lenStr}`);
65+
}
66+
67+
export function logRequestSuccess(
68+
logger: vscode.LogOutputChannel,
69+
meta: RequestMeta,
70+
response: AxiosResponse,
71+
): void {
72+
const method = (response.config.method ?? "GET").toUpperCase();
73+
const url = response.config.url || "";
74+
const len = response.headers?.["content-length"] as string | undefined;
75+
const ms = Date.now() - meta.startedAt;
76+
const lenStr = len ? ` (${len}b)` : "";
77+
logger.trace(
78+
`← ${shortId(meta.requestId)} ${response.status} ${method} ${url} ${ms}ms${lenStr}`,
79+
);
80+
}
81+
82+
export function logRequestError(
83+
logger: vscode.LogOutputChannel,
84+
error: AxiosError | unknown,
85+
): void {
86+
if (isAxiosError(error)) {
87+
const config = error.config as RequestConfigWithMeta | undefined;
88+
const meta = config?.metadata;
89+
const method = (config?.method ?? "GET").toUpperCase();
90+
const url = config?.url || "";
91+
const requestId = meta?.requestId ?? "unknown";
92+
const ms = meta ? Date.now() - meta.startedAt : "?";
93+
94+
if (error.response) {
95+
// Response error (4xx, 5xx status codes)
96+
const msg =
97+
error.response.statusText || String(error.response.data).slice(0, 100);
98+
logger.error(
99+
`← ${shortId(requestId)} ${error.response.status} ${method} ${url} ${ms}ms - ${msg}`,
100+
error,
101+
);
102+
} else {
103+
// Request error (network, timeout, etc)
104+
const reason = error.code || error.message || "Network error";
105+
logger.error(
106+
`✗ ${shortId(requestId)} ${method} ${url} ${ms}ms - ${reason}`,
107+
error,
108+
);
109+
}
110+
} else {
111+
logger.error("Request error", error);
112+
}
113+
}
114+
115+
export class WsLogger {
116+
private logger: vscode.LogOutputChannel;
117+
private url: string;
118+
private id: string;
119+
private startedAt: number;
120+
private openedAt?: number;
121+
private msgCount = 0;
122+
private byteCount = 0;
123+
124+
constructor(logger: vscode.LogOutputChannel, url: string) {
125+
this.logger = logger;
126+
this.url = url;
127+
this.id = crypto.randomUUID().replace(/-/g, "");
128+
this.startedAt = Date.now();
129+
}
130+
131+
logConnecting(): void {
132+
this.logger.trace(`→ WS ${shortId(this.id)} ${this.url}`);
133+
}
134+
135+
logOpen(): void {
136+
this.openedAt = Date.now();
137+
const connectMs = this.openedAt - this.startedAt;
138+
this.logger.trace(`← WS ${shortId(this.id)} connected ${connectMs}ms`);
139+
}
140+
141+
logMessage(data: unknown): void {
142+
this.msgCount += 1;
143+
this.byteCount += sizeOf(data);
144+
}
145+
146+
logClose(code?: number, reason?: string): void {
147+
const upMs = this.openedAt ? Date.now() - this.openedAt : 0;
148+
const stats = [];
149+
if (upMs > 0) {
150+
stats.push(`${upMs}ms`);
151+
}
152+
if (this.msgCount > 0) {
153+
stats.push(`${this.msgCount} msgs`);
154+
}
155+
if (this.byteCount > 0) {
156+
stats.push(`${this.byteCount}b`);
157+
}
158+
159+
const codeStr = code ? ` (${code})` : "";
160+
const reasonStr = reason ? ` - ${reason}` : "";
161+
const statsStr = stats.length > 0 ? ` [${stats.join(", ")}]` : "";
162+
163+
this.logger.trace(
164+
`✗ WS ${shortId(this.id)} closed${codeStr}${reasonStr}${statsStr}`,
165+
);
166+
}
167+
168+
logError(error: unknown): void {
169+
const ms = Date.now() - this.startedAt;
170+
const errorMsg = errToStr(error, "connection error");
171+
this.logger.error(
172+
`✗ WS ${shortId(this.id)} error ${ms}ms - ${errorMsg}`,
173+
error,
174+
);
175+
}
176+
}

src/websocket/webSocketClient.ts

Lines changed: 17 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ import {
99
import { ProxyAgent } from "proxy-agent";
1010
import { ClientOptions } from "ws";
1111
import { coderSessionTokenHeader } from "../api";
12-
import { errToStr } from "../api-helper";
12+
import { WsLogger } from "../logging/netLog";
1313
import { Storage } from "../storage";
1414
import { OneWayCodeWebSocket } from "./oneWayCodeWebSocket";
1515

@@ -86,53 +86,44 @@ export class CoderWebSocketClient {
8686
throw new Error("No base URL set on REST client");
8787
}
8888

89-
// We shouldn't need to worry about this throwing. Whilst `baseURL` could
90-
// be an invalid URL, that would've caused issues before we got to here.
9189
const baseUrl = new URL(baseUrlRaw);
9290
const token = this.client.getAxiosInstance().defaults.headers.common[
9391
coderSessionTokenHeader
9492
] as string | undefined;
9593

96-
// Log WebSocket connection attempt
97-
this.storage.output.trace(
98-
`Creating WebSocket connection to ${configs.apiRoute}`,
99-
);
100-
10194
const webSocket = new OneWayCodeWebSocket<TData>({
10295
location: baseUrl,
10396
...configs,
10497
options: {
10598
agent: this.httpAgent,
10699
followRedirects: true,
107-
headers: token
108-
? {
109-
[coderSessionTokenHeader]: token,
110-
...configs.options?.headers,
111-
}
112-
: configs.options?.headers,
100+
headers: {
101+
...(token ? { [coderSessionTokenHeader]: token } : {}),
102+
...configs.options?.headers,
103+
},
113104
...configs.options,
114105
},
115106
});
116107

117-
// Add logging for WebSocket events
108+
const wsUrl = new URL(webSocket.url);
109+
const pathWithQuery = wsUrl.pathname + wsUrl.search;
110+
const wsLogger = new WsLogger(this.storage.output, pathWithQuery);
111+
wsLogger.logConnecting();
112+
118113
webSocket.addEventListener("open", () => {
119-
this.storage.output.trace(
120-
`WebSocket connection opened to ${configs.apiRoute}`,
121-
);
114+
wsLogger.logOpen();
115+
});
116+
117+
webSocket.addEventListener("message", (event) => {
118+
wsLogger.logMessage(event.sourceEvent.data);
122119
});
123120

124121
webSocket.addEventListener("close", (event) => {
125-
this.storage.output.trace(
126-
`WebSocket connection closed to ${configs.apiRoute}, code: ${event.code}, reason: ${event.reason}`,
127-
);
122+
wsLogger.logClose(event.code, event.reason);
128123
});
129124

130125
webSocket.addEventListener("error", (event) => {
131-
const err = errToStr(
132-
event.error,
133-
`Got empty error while monitoring ${configs.apiRoute}`,
134-
);
135-
this.storage.output.error(err);
126+
wsLogger.logError(event?.error ?? event);
136127
});
137128

138129
return webSocket;

0 commit comments

Comments
 (0)