From 4c6dd808f221b4f64e5505f1d545bdad1d0820e7 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Tue, 10 Sep 2024 11:08:00 +0200 Subject: [PATCH] fix(node): Remove ambiguity and race conditions when matching local variables to exceptions (#13501) Closes #13415 This PR only modifies the async version of this integration which is used for Node > v19. I tried applying similar changes to the sync integration and I cannot get it to work without causing memory leaks. @Bruno-DaSilva has been helping me explore different ways to fix a few fundamental issues with the local variables integration. Bruno found a way to [write to the error object](https://github.com/getsentry/sentry-javascript/issues/13415#issuecomment-2313754556) from the debugger which removes any ambiguity over which variables go with which exception. This allows us to remove the stack parsing and hashing which we were using previously to match up exceptions. Rather than write the `objectId` to the error, I have used this to write the entire local variables array directly to the error object. This completely negates the need to post the local variables from the worker thread which removes any possibility of race conditions. We then later pull the local variables directly from `hint.originalException.__SENTRY_ERROR_LOCAL_VARIABLES__`. --- .../integrations/local-variables/common.ts | 29 ++------- .../local-variables/inspector.d.ts | 8 +++ .../local-variables/local-variables-async.ts | 62 ++++++++----------- .../local-variables/local-variables-sync.ts | 26 +++++++- .../integrations/local-variables/worker.ts | 48 ++++++++------ 5 files changed, 93 insertions(+), 80 deletions(-) diff --git a/packages/node/src/integrations/local-variables/common.ts b/packages/node/src/integrations/local-variables/common.ts index 67c8d6d43d81..58ccea70d6de 100644 --- a/packages/node/src/integrations/local-variables/common.ts +++ b/packages/node/src/integrations/local-variables/common.ts @@ -1,10 +1,14 @@ import type { Debugger } from 'node:inspector'; -import type { StackFrame, StackParser } from '@sentry/types'; export type Variables = Record; export type RateLimitIncrement = () => void; +/** + * The key used to store the local variables on the error object. + */ +export const LOCAL_VARIABLES_KEY = '__SENTRY_ERROR_LOCAL_VARIABLES__'; + /** * Creates a rate limiter that will call the disable callback when the rate limit is reached and the enable callback * when a timeout has occurred. @@ -55,6 +59,7 @@ export type PausedExceptionEvent = Debugger.PausedEventDataType & { data: { // This contains error.stack description: string; + objectId?: string; }; }; @@ -68,28 +73,6 @@ export function functionNamesMatch(a: string | undefined, b: string | undefined) return a === b || (isAnonymous(a) && isAnonymous(b)); } -/** Creates a unique hash from stack frames */ -export function hashFrames(frames: StackFrame[] | undefined): string | undefined { - if (frames === undefined) { - return; - } - - // Only hash the 10 most recent frames (ie. the last 10) - return frames.slice(-10).reduce((acc, frame) => `${acc},${frame.function},${frame.lineno},${frame.colno}`, ''); -} - -/** - * We use the stack parser to create a unique hash from the exception stack trace - * This is used to lookup vars when the exception passes through the event processor - */ -export function hashFromStack(stackParser: StackParser, stack: string | undefined): string | undefined { - if (stack === undefined) { - return undefined; - } - - return hashFrames(stackParser(stack, 1)); -} - export interface FrameVariables { function: string; vars?: Variables; diff --git a/packages/node/src/integrations/local-variables/inspector.d.ts b/packages/node/src/integrations/local-variables/inspector.d.ts index 9ac6b857dcc0..5cfd496f7626 100644 --- a/packages/node/src/integrations/local-variables/inspector.d.ts +++ b/packages/node/src/integrations/local-variables/inspector.d.ts @@ -20,6 +20,14 @@ declare module 'node:inspector/promises' { method: 'Runtime.getProperties', params: Runtime.GetPropertiesParameterType, ): Promise; + public post( + method: 'Runtime.callFunctionOn', + params: Runtime.CallFunctionOnParameterType, + ): Promise; + public post( + method: 'Runtime.releaseObject', + params: Runtime.ReleaseObjectParameterType, + ): Promise; public on( event: 'Debugger.paused', diff --git a/packages/node/src/integrations/local-variables/local-variables-async.ts b/packages/node/src/integrations/local-variables/local-variables-async.ts index 86ce9359a95e..d46fa224019f 100644 --- a/packages/node/src/integrations/local-variables/local-variables-async.ts +++ b/packages/node/src/integrations/local-variables/local-variables-async.ts @@ -1,11 +1,12 @@ import { Worker } from 'node:worker_threads'; import { defineIntegration } from '@sentry/core'; -import type { Event, Exception, IntegrationFn } from '@sentry/types'; -import { LRUMap, logger } from '@sentry/utils'; +import type { Event, EventHint, Exception, IntegrationFn } from '@sentry/types'; +import { logger } from '@sentry/utils'; import type { NodeClient } from '../../sdk/client'; import type { FrameVariables, LocalVariablesIntegrationOptions, LocalVariablesWorkerArgs } from './common'; -import { functionNamesMatch, hashFrames } from './common'; +import { LOCAL_VARIABLES_KEY } from './common'; +import { functionNamesMatch } from './common'; // This string is a placeholder that gets overwritten with the worker code. export const base64WorkerScript = '###LocalVariablesWorkerScript###'; @@ -20,23 +21,7 @@ function log(...args: unknown[]): void { export const localVariablesAsyncIntegration = defineIntegration((( integrationOptions: LocalVariablesIntegrationOptions = {}, ) => { - const cachedFrames: LRUMap = new LRUMap(20); - - function addLocalVariablesToException(exception: Exception): void { - const hash = hashFrames(exception?.stacktrace?.frames); - - if (hash === undefined) { - return; - } - - // Check if we have local variables for an exception that matches the hash - // remove is identical to get but also removes the entry from the cache - const cachedFrame = cachedFrames.remove(hash); - - if (cachedFrame === undefined) { - return; - } - + function addLocalVariablesToException(exception: Exception, localVariables: FrameVariables[]): void { // Filter out frames where the function name is `new Promise` since these are in the error.stack frames // but do not appear in the debugger call frames const frames = (exception.stacktrace?.frames || []).filter(frame => frame.function !== 'new Promise'); @@ -45,32 +30,41 @@ export const localVariablesAsyncIntegration = defineIntegration((( // Sentry frames are in reverse order const frameIndex = frames.length - i - 1; - const cachedFrameVariable = cachedFrame[i]; - const frameVariable = frames[frameIndex]; + const frameLocalVariables = localVariables[i]; + const frame = frames[frameIndex]; - if (!frameVariable || !cachedFrameVariable) { + if (!frame || !frameLocalVariables) { // Drop out if we run out of frames to match up break; } if ( // We need to have vars to add - cachedFrameVariable.vars === undefined || + frameLocalVariables.vars === undefined || // We're not interested in frames that are not in_app because the vars are not relevant - frameVariable.in_app === false || + frame.in_app === false || // The function names need to match - !functionNamesMatch(frameVariable.function, cachedFrameVariable.function) + !functionNamesMatch(frame.function, frameLocalVariables.function) ) { continue; } - frameVariable.vars = cachedFrameVariable.vars; + frame.vars = frameLocalVariables.vars; } } - function addLocalVariablesToEvent(event: Event): Event { - for (const exception of event.exception?.values || []) { - addLocalVariablesToException(exception); + function addLocalVariablesToEvent(event: Event, hint: EventHint): Event { + if ( + hint.originalException && + typeof hint.originalException === 'object' && + LOCAL_VARIABLES_KEY in hint.originalException && + Array.isArray(hint.originalException[LOCAL_VARIABLES_KEY]) + ) { + for (const exception of event.exception?.values || []) { + addLocalVariablesToException(exception, hint.originalException[LOCAL_VARIABLES_KEY]); + } + + hint.originalException[LOCAL_VARIABLES_KEY] = undefined; } return event; @@ -96,10 +90,6 @@ export const localVariablesAsyncIntegration = defineIntegration((( worker.terminate(); }); - worker.on('message', ({ exceptionHash, frames }) => { - cachedFrames.set(exceptionHash, frames); - }); - worker.once('error', (err: Error) => { log('Worker error', err); }); @@ -139,8 +129,8 @@ export const localVariablesAsyncIntegration = defineIntegration((( }, ); }, - processEvent(event: Event): Event { - return addLocalVariablesToEvent(event); + processEvent(event: Event, hint: EventHint): Event { + return addLocalVariablesToEvent(event, hint); }, }; }) satisfies IntegrationFn); diff --git a/packages/node/src/integrations/local-variables/local-variables-sync.ts b/packages/node/src/integrations/local-variables/local-variables-sync.ts index bf7aaa26cbf3..d3203614330f 100644 --- a/packages/node/src/integrations/local-variables/local-variables-sync.ts +++ b/packages/node/src/integrations/local-variables/local-variables-sync.ts @@ -1,6 +1,6 @@ import type { Debugger, InspectorNotification, Runtime, Session } from 'node:inspector'; import { defineIntegration, getClient } from '@sentry/core'; -import type { Event, Exception, IntegrationFn, StackParser } from '@sentry/types'; +import type { Event, Exception, IntegrationFn, StackFrame, StackParser } from '@sentry/types'; import { LRUMap, logger } from '@sentry/utils'; import { NODE_MAJOR } from '../../nodeVersion'; @@ -12,7 +12,29 @@ import type { RateLimitIncrement, Variables, } from './common'; -import { createRateLimiter, functionNamesMatch, hashFrames, hashFromStack } from './common'; +import { createRateLimiter, functionNamesMatch } from './common'; + +/** Creates a unique hash from stack frames */ +export function hashFrames(frames: StackFrame[] | undefined): string | undefined { + if (frames === undefined) { + return; + } + + // Only hash the 10 most recent frames (ie. the last 10) + return frames.slice(-10).reduce((acc, frame) => `${acc},${frame.function},${frame.lineno},${frame.colno}`, ''); +} + +/** + * We use the stack parser to create a unique hash from the exception stack trace + * This is used to lookup vars when the exception passes through the event processor + */ +export function hashFromStack(stackParser: StackParser, stack: string | undefined): string | undefined { + if (stack === undefined) { + return undefined; + } + + return hashFrames(stackParser(stack, 1)); +} type OnPauseEvent = InspectorNotification; export interface DebugSession { diff --git a/packages/node/src/integrations/local-variables/worker.ts b/packages/node/src/integrations/local-variables/worker.ts index 5bee22a84c29..eb4fee87947c 100644 --- a/packages/node/src/integrations/local-variables/worker.ts +++ b/packages/node/src/integrations/local-variables/worker.ts @@ -1,16 +1,12 @@ import type { Debugger, InspectorNotification, Runtime } from 'node:inspector'; import { Session } from 'node:inspector/promises'; -import { parentPort, workerData } from 'node:worker_threads'; -import type { StackParser } from '@sentry/types'; -import { createStackParser, nodeStackLineParser } from '@sentry/utils'; -import { createGetModuleFromFilename } from '../../utils/module'; +import { workerData } from 'node:worker_threads'; import type { LocalVariablesWorkerArgs, PausedExceptionEvent, RateLimitIncrement, Variables } from './common'; -import { createRateLimiter, hashFromStack } from './common'; +import { LOCAL_VARIABLES_KEY } from './common'; +import { createRateLimiter } from './common'; const options: LocalVariablesWorkerArgs = workerData; -const stackParser = createStackParser(nodeStackLineParser(createGetModuleFromFilename(options.basePath))); - function log(...args: unknown[]): void { if (options.debug) { // eslint-disable-next-line no-console @@ -88,19 +84,15 @@ let rateLimiter: RateLimitIncrement | undefined; async function handlePaused( session: Session, - stackParser: StackParser, - { reason, data, callFrames }: PausedExceptionEvent, -): Promise { + { reason, data: { objectId }, callFrames }: PausedExceptionEvent, +): Promise { if (reason !== 'exception' && reason !== 'promiseRejection') { return; } rateLimiter?.(); - // data.description contains the original error.stack - const exceptionHash = hashFromStack(stackParser, data?.description); - - if (exceptionHash == undefined) { + if (objectId == undefined) { return; } @@ -123,7 +115,15 @@ async function handlePaused( } } - parentPort?.postMessage({ exceptionHash, frames }); + // We write the local variables to a property on the error object. These can be read by the integration as the error + // event pass through the SDK event pipeline + await session.post('Runtime.callFunctionOn', { + functionDeclaration: `function() { this.${LOCAL_VARIABLES_KEY} = ${JSON.stringify(frames)}; }`, + silent: true, + objectId, + }); + + return objectId; } async function startDebugger(): Promise { @@ -141,13 +141,23 @@ async function startDebugger(): Promise { session.on('Debugger.paused', (event: InspectorNotification) => { isPaused = true; - handlePaused(session, stackParser, event.params as PausedExceptionEvent).then( - () => { + handlePaused(session, event.params as PausedExceptionEvent).then( + async objectId => { // After the pause work is complete, resume execution! - return isPaused ? session.post('Debugger.resume') : Promise.resolve(); + if (isPaused) { + await session.post('Debugger.resume'); + } + + if (objectId) { + // The object must be released after the debugger has resumed or we get a memory leak. + // For node v20, setImmediate is enough here but for v22 a longer delay is required + setTimeout(async () => { + await session.post('Runtime.releaseObject', { objectId }); + }, 1_000); + } }, _ => { - // ignore + // ignore any errors }, ); });