From a20013a5d2231e50def4c3b45281aa250c283eba Mon Sep 17 00:00:00 2001 From: Brian Ingles Date: Mon, 27 Jan 2025 10:59:57 -0600 Subject: [PATCH] feat: gRPC transport logging (#209) DH-18086: gRPC transport logging ### Testing I tested this using a local http1 proxy on a Grizzly dev server to see errors logged via gRPC transport. I was able to see the following when creating new Core+ workers: ``` [NodeHttp2gRPCTransport] ERROR: Session error Error: Protocol error at Http2Session.onSessionInternalError (node:internal/http2/core:793:26) at Http2Session.callbackTrampoline (node:internal/async_hooks:130:17) ``` I also tested without the proxy and can see debug messages for gRPC transport communication. This is easy to test by connecting a server and looking at the Output -> Deephaven Debug panel and looking for [NodeHttp2gRPCTransport] messages. --- package-lock.json | 46 +++++++++---------- package.json | 2 +- src/common/constants.ts | 2 + src/controllers/ExtensionController.ts | 11 +++++ src/controllers/PanelController.ts | 12 ++++- src/util/Logger.ts | 43 +++++++++++++++--- src/util/dataUtils.ts | 13 ++++++ src/util/index.ts | 1 + src/util/sanitizeUtils.ts | 61 ++++++++++++++++++++++++++ 9 files changed, 160 insertions(+), 31 deletions(-) create mode 100644 src/util/sanitizeUtils.ts diff --git a/package-lock.json b/package-lock.json index 61da4fcf..f003a2bf 100644 --- a/package-lock.json +++ b/package-lock.json @@ -13,7 +13,7 @@ "dependencies": { "@deephaven-enterprise/auth-nodejs": "^1.20240723.124-beta", "@deephaven-enterprise/query-utils": "^1.20240723.124-beta", - "@deephaven/jsapi-nodejs": "^0.103.0", + "@deephaven/jsapi-nodejs": "^0.104.0", "nanoid": "^5.0.7" }, "devDependencies": { @@ -467,12 +467,12 @@ } }, "node_modules/@deephaven/jsapi-nodejs": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/jsapi-nodejs/-/jsapi-nodejs-0.103.0.tgz", - "integrity": "sha512-dkAi321+Jx56STJK9jTrpyhiTigPDz5/sFBiXHsj/fHRYpdKieUFFAxEu3rYfy5gDOFs7EXB50VSQI7FP0D7iQ==", + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/jsapi-nodejs/-/jsapi-nodejs-0.104.0.tgz", + "integrity": "sha512-e284BE+MYIwN9Nflb13M9Hxs8ZQS2k1z1S7uZGqZQYsci85vhIAoCWhpU+UX2YUlhR8+QE0Aehf8ywheWF+W2g==", "dependencies": { - "@deephaven/log": "^0.103.0", - "@deephaven/utils": "^0.103.0", + "@deephaven/log": "^0.104.0", + "@deephaven/utils": "^0.104.0", "ws": "^8.18.0" }, "engines": { @@ -480,9 +480,9 @@ } }, "node_modules/@deephaven/jsapi-nodejs/node_modules/@deephaven/log": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/log/-/log-0.103.0.tgz", - "integrity": "sha512-8vQktsmaoJrPwZIZALRyFAWyYhFg5DzaN0Ye7HObe3n/kBBe5+GXbhv0F/AUbMzLngYkj7WLIXjsDzYRw70qNQ==", + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/log/-/log-0.104.0.tgz", + "integrity": "sha512-xsGSmdVNjCXF9Zii7/VitzX5mDpcST/MzTRA+bLgtHlChKEcw9U46rU68RPJKfKuW4BpGBQCvoMI4pKC+quZiw==", "dependencies": { "event-target-shim": "^6.0.2", "jszip": "^3.10.1" @@ -492,9 +492,9 @@ } }, "node_modules/@deephaven/jsapi-nodejs/node_modules/@deephaven/utils": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/utils/-/utils-0.103.0.tgz", - "integrity": "sha512-1N0bBG5fpl89Ktt1Y0CUj3thl2uFFgHUMqJMvBje5D38DIuuu7VUifEXtFGcOSgi67z62hkFt0ODLWMzZuZcEQ==", + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/utils/-/utils-0.104.0.tgz", + "integrity": "sha512-KxWmrgHarAZ2fYP3R2ee2LjA3lUiYKK3zbxi1cu9V2jAi+H3iaUn1Xl/FIkCjq2Q5wrOfTkuKgg9MyG61DREyA==", "engines": { "node": ">=16" } @@ -15516,28 +15516,28 @@ } }, "@deephaven/jsapi-nodejs": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/jsapi-nodejs/-/jsapi-nodejs-0.103.0.tgz", - "integrity": "sha512-dkAi321+Jx56STJK9jTrpyhiTigPDz5/sFBiXHsj/fHRYpdKieUFFAxEu3rYfy5gDOFs7EXB50VSQI7FP0D7iQ==", + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/jsapi-nodejs/-/jsapi-nodejs-0.104.0.tgz", + "integrity": "sha512-e284BE+MYIwN9Nflb13M9Hxs8ZQS2k1z1S7uZGqZQYsci85vhIAoCWhpU+UX2YUlhR8+QE0Aehf8ywheWF+W2g==", "requires": { - "@deephaven/log": "^0.103.0", - "@deephaven/utils": "^0.103.0", + "@deephaven/log": "^0.104.0", + "@deephaven/utils": "^0.104.0", "ws": "^8.18.0" }, "dependencies": { "@deephaven/log": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/log/-/log-0.103.0.tgz", - "integrity": "sha512-8vQktsmaoJrPwZIZALRyFAWyYhFg5DzaN0Ye7HObe3n/kBBe5+GXbhv0F/AUbMzLngYkj7WLIXjsDzYRw70qNQ==", + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/log/-/log-0.104.0.tgz", + "integrity": "sha512-xsGSmdVNjCXF9Zii7/VitzX5mDpcST/MzTRA+bLgtHlChKEcw9U46rU68RPJKfKuW4BpGBQCvoMI4pKC+quZiw==", "requires": { "event-target-shim": "^6.0.2", "jszip": "^3.10.1" } }, "@deephaven/utils": { - "version": "0.103.0", - "resolved": "https://registry.npmjs.org/@deephaven/utils/-/utils-0.103.0.tgz", - "integrity": "sha512-1N0bBG5fpl89Ktt1Y0CUj3thl2uFFgHUMqJMvBje5D38DIuuu7VUifEXtFGcOSgi67z62hkFt0ODLWMzZuZcEQ==" + "version": "0.104.0", + "resolved": "https://registry.npmjs.org/@deephaven/utils/-/utils-0.104.0.tgz", + "integrity": "sha512-KxWmrgHarAZ2fYP3R2ee2LjA3lUiYKK3zbxi1cu9V2jAi+H3iaUn1Xl/FIkCjq2Q5wrOfTkuKgg9MyG61DREyA==" } } }, diff --git a/package.json b/package.json index 735bec4a..677f3dce 100644 --- a/package.json +++ b/package.json @@ -870,7 +870,7 @@ "dependencies": { "@deephaven-enterprise/auth-nodejs": "^1.20240723.124-beta", "@deephaven-enterprise/query-utils": "^1.20240723.124-beta", - "@deephaven/jsapi-nodejs": "^0.103.0", + "@deephaven/jsapi-nodejs": "^0.104.0", "nanoid": "^5.0.7" }, "devDependencies": { diff --git a/src/common/constants.ts b/src/common/constants.ts index a0ef2a77..3d12faca 100644 --- a/src/common/constants.ts +++ b/src/common/constants.ts @@ -9,6 +9,8 @@ export const CONFIG_KEY = { enterpriseServers: 'enterpriseServers', } as const; +export const CENSORED_TEXT = '********' as const; + export const DEFAULT_CONSOLE_TYPE = 'python' as const; // export const DHFS_SCHEME = 'dhfs'; diff --git a/src/controllers/ExtensionController.ts b/src/controllers/ExtensionController.ts index 524cb38d..02b1cb65 100644 --- a/src/controllers/ExtensionController.ts +++ b/src/controllers/ExtensionController.ts @@ -34,6 +34,7 @@ import { isSupportedLanguageId, Logger, OutputChannelWithHistory, + sanitizeGRPCLogMessageArgs, Toaster, } from '../util'; import { @@ -107,6 +108,8 @@ export class ExtensionController implements Disposable { this.initializeWebViews(); this.initializeServerUpdates(); + this._context.subscriptions.push(NodeHttp2gRPCTransport); + logger.info( 'Congratulations, your extension "vscode-deephaven" is now active!' ); @@ -317,6 +320,14 @@ export class ExtensionController implements Disposable { Logger.addConsoleHandler(); Logger.addOutputChannelHandler(this._outputChannelDebug); + const gRPCOutputChannelHandler = Logger.createOutputChannelHandler( + this._outputChannelDebug + ); + NodeHttp2gRPCTransport.onLogMessage((logLevel, ...args: unknown[]) => { + args = sanitizeGRPCLogMessageArgs(args); + gRPCOutputChannelHandler(logLevel)('[NodeHttp2gRPCTransport]', ...args); + }); + this._toaster = new Toaster(); this._context.subscriptions.push( diff --git a/src/controllers/PanelController.ts b/src/controllers/PanelController.ts index ce6147c3..e34d480a 100644 --- a/src/controllers/PanelController.ts +++ b/src/controllers/PanelController.ts @@ -19,6 +19,7 @@ import { } from '../util'; import { DhcService } from '../services'; import { + CENSORED_TEXT, DEEPHAVEN_POST_MSG, DH_PANEL_VIEW_TYPE, OPEN_VARIABLE_PANELS_CMD, @@ -161,7 +162,16 @@ export class PanelController extends ControllerBase { workerInfo, }); - logger.debug('Posting LoginOptions response:', response); + logger.debug('Posting LoginOptions response:', { + ...response, + payload: { + ...response.payload, + payload: { + ...response.payload.payload, + token: CENSORED_TEXT, + }, + }, + }); postResponseMessage(response); diff --git a/src/util/Logger.ts b/src/util/Logger.ts index acb1f37f..ab1c50a7 100644 --- a/src/util/Logger.ts +++ b/src/util/Logger.ts @@ -41,6 +41,42 @@ export class Logger { }); }; + /** + * Stringify an argument for logging. + * @param arg The argument to stringify. + * @returns The stringified argument. + */ + static stringifyArg = (arg: unknown): string => { + if (arg instanceof Error) { + return arg.stack ?? arg.message; + } + + if (typeof arg === 'string') { + return arg; + } + + try { + return JSON.stringify(arg); + } catch { + return String(arg); + } + }; + + /** + * Create a log handler that logs to a `vscode.OutputChannel`. + * @param outputChannel The output channel to log to. + * @returns A log handler that logs to the output channel. + */ + static createOutputChannelHandler = ( + outputChannel: vscode.OutputChannel + ): ((level: LogLevel) => LogLevelHandler) => { + return (level: LogLevel): LogLevelHandler => + (label, ...args) => + outputChannel.appendLine( + `${label} ${level.toUpperCase()}: ${args.map(Logger.stringifyArg).join(' ')}` + ); + }; + /** * Register a log handler that logs to a `vscode.OutputChannel`. * @param outputChannel @@ -48,12 +84,7 @@ export class Logger { static addOutputChannelHandler = ( outputChannel: vscode.OutputChannel ): void => { - const createHandler = - (level: LogLevel): LogLevelHandler => - (label, ...args) => - outputChannel.appendLine( - `${label} ${level.toUpperCase()}: ${args.map(a => (a instanceof Error ? (a.stack ?? a.message) : a)).join(' ')}` - ); + const createHandler = Logger.createOutputChannelHandler(outputChannel); Logger.handlers.add({ error: createHandler('error'), diff --git a/src/util/dataUtils.ts b/src/util/dataUtils.ts index 99b3fa9c..826f8f91 100644 --- a/src/util/dataUtils.ts +++ b/src/util/dataUtils.ts @@ -1,5 +1,18 @@ import type { NonEmptyArray } from '../types'; +/** + * Type guard to determine if an object has a property. + * @param obj The object to check. + * @param prop The property to check for. + * @returns true if the property exists, false otherwise. + */ +export function hasProperty( + obj: unknown, + prop: TProp +): obj is Record { + return obj != null && typeof obj === 'object' && prop in obj; +} + /** * Type guard to check if an array is non-empty. * @param array diff --git a/src/util/index.ts b/src/util/index.ts index 7ff2bbf5..8d27d17d 100644 --- a/src/util/index.ts +++ b/src/util/index.ts @@ -7,6 +7,7 @@ export * from './Logger'; export * from './OutputChannelWithHistory'; export * from './panelUtils'; export * from './promiseUtils'; +export * from './sanitizeUtils'; export * from './selectionUtils'; export * from './serverUtils'; export * from './testUtils'; diff --git a/src/util/sanitizeUtils.ts b/src/util/sanitizeUtils.ts new file mode 100644 index 00000000..eb9d3925 --- /dev/null +++ b/src/util/sanitizeUtils.ts @@ -0,0 +1,61 @@ +import { CENSORED_TEXT } from '../common'; +import { hasProperty } from './dataUtils'; + +/** + * Sanitize an auth header value. + * @param authHeaderValue Sanitize secret portion of known auth headers. If + * unrecognized, replace the whole thing. + * @returns The sanitized auth header value. + */ +export function sanitizeAuthHeaderValue(authHeaderValue: string): string { + if ( + authHeaderValue.startsWith('io.deephaven.proto.auth.Token') || + authHeaderValue.startsWith('Bearer') + ) { + return authHeaderValue.replace(/ \S+$/, ` ${CENSORED_TEXT}`); + } + + return CENSORED_TEXT; +} + +/** + * Sanitize an auth header. + * @param authorization The authorization header value. This can be a string + * or an array of strings. Any other data types will be treated as an empty + * string. + * @returns The sanitized auth header value. + */ +export function sanitizeAuthHeader(authorization: unknown): string | string[] { + if (typeof authorization === 'string') { + return sanitizeAuthHeaderValue(authorization); + } + + if (Array.isArray(authorization)) { + return authorization.map(sanitizeAuthHeaderValue); + } + + return CENSORED_TEXT; +} + +/** + * Sanitize auth headers in a gRPC log message. + * @param args The arguments to sanitize. + * @returns The sanitized arguments. + */ +export function sanitizeGRPCLogMessageArgs([ + arg0, + arg1, + ...args +]: unknown[]): unknown[] { + if (arg0 === 'start' && hasProperty(arg1, 'authorization')) { + return [ + arg0, + { + ...arg1, + authorization: sanitizeAuthHeader(arg1.authorization), + }, + ]; + } + + return [arg0, arg1, ...args]; +}