Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(node): Remove ambiguity and race conditions when matching local variables to exceptions #13501

Merged
merged 10 commits into from
Sep 10, 2024
29 changes: 6 additions & 23 deletions packages/node/src/integrations/local-variables/common.ts
Original file line number Diff line number Diff line change
@@ -1,10 +1,14 @@
import type { Debugger } from 'node:inspector';
import type { StackFrame, StackParser } from '@sentry/types';

export type Variables = Record<string, unknown>;

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.
Expand Down Expand Up @@ -55,6 +59,7 @@ export type PausedExceptionEvent = Debugger.PausedEventDataType & {
data: {
// This contains error.stack
description: string;
objectId?: string;
};
};

Expand All @@ -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;
Expand Down
8 changes: 8 additions & 0 deletions packages/node/src/integrations/local-variables/inspector.d.ts
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,14 @@ declare module 'node:inspector/promises' {
method: 'Runtime.getProperties',
params: Runtime.GetPropertiesParameterType,
): Promise<Runtime.GetPropertiesReturnType>;
public post(
method: 'Runtime.callFunctionOn',
params: Runtime.CallFunctionOnParameterType,
): Promise<Runtime.CallFunctionOnReturnType>;
public post(
method: 'Runtime.releaseObject',
params: Runtime.ReleaseObjectParameterType,
): Promise<Runtime.ReleaseObjectReturnType>;

public on(
event: 'Debugger.paused',
Expand Down
Original file line number Diff line number Diff line change
@@ -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###';
Expand All @@ -20,23 +21,7 @@ function log(...args: unknown[]): void {
export const localVariablesAsyncIntegration = defineIntegration(((
integrationOptions: LocalVariablesIntegrationOptions = {},
) => {
const cachedFrames: LRUMap<string, FrameVariables[]> = 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');
Expand All @@ -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;
Comment on lines +56 to +67

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

in both here and the worker, is it worth adding some kind of debug logging for when the sdk is in debug mode?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can validate it pretty easily by inspecting the event in beforeSend, so I think we don't explicitly need logging for every event, but @timfish if you think it's a good idea go for it.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's also the discussion over whether some of our logging here should be behind debug: true or regular console.*. If we hit rate limiting maybe this should always be logged rather than only when debug is enabled? Users are unlikely to have debug logging enabled in production but it's likely useful to know when you're hitting rate limiting.

}

return event;
Expand All @@ -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);
});
Expand Down Expand Up @@ -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);
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
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 { LRUMap, logger } from '@sentry/utils';
import type { Event, EventHint, Exception, IntegrationFn } from '@sentry/types';
import { logger } from '@sentry/utils';

import { NODE_MAJOR } from '../../nodeVersion';
import type { NodeClient } from '../../sdk/client';
Expand All @@ -12,7 +12,8 @@
RateLimitIncrement,
Variables,
} from './common';
import { createRateLimiter, functionNamesMatch, hashFrames, hashFromStack } from './common';
import { LOCAL_VARIABLES_KEY } from './common';
import { createRateLimiter, functionNamesMatch } from './common';

type OnPauseEvent = InspectorNotification<Debugger.PausedEventDataType>;
export interface DebugSession {
Expand All @@ -22,6 +23,8 @@
setPauseOnExceptions(captureAll: boolean): void;
/** Gets local variables for an objectId */
getLocalVariables(objectId: string, callback: (vars: Variables) => void): void;
/** Sets the local variables on the error object for later retrieval */
setLocalVarsOnError(objectId: string, localVariables: FrameVariables[]): void;
}

type Next<T> = (result: T) => void;
Expand Down Expand Up @@ -128,6 +131,14 @@
});
}

public setLocalVarsOnError(objectId: string, localVariables: FrameVariables[]): void {
this._session.post('Runtime.callFunctionOn', {
functionDeclaration: `function() { this.${LOCAL_VARIABLES_KEY} = ${JSON.stringify(localVariables)}; }`,
Fixed Show fixed Hide fixed
Fixed Show fixed Hide fixed
silent: true,
objectId,
});
}

/**
* Gets all the PropertyDescriptors of an object
*/
Expand Down Expand Up @@ -209,25 +220,10 @@
options: LocalVariablesIntegrationOptions = {},
sessionOverride?: DebugSession,
) => {
const cachedFrames: LRUMap<string, FrameVariables[]> = new LRUMap(20);
let rateLimiter: RateLimitIncrement | undefined;
let shouldProcessEvent = false;

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');
Expand All @@ -236,32 +232,41 @@
// 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];

// Drop out if we run out of frames to match up
if (!frameVariable || !cachedFrameVariable) {
if (!frame || !frameLocalVariables) {
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;
Expand Down Expand Up @@ -289,7 +294,6 @@
AsyncSession.create(sessionOverride).then(
session => {
function handlePaused(
stackParser: StackParser,
{ params: { reason, data, callFrames } }: InspectorNotification<PausedExceptionEvent>,
complete: () => void,
): void {
Expand All @@ -300,16 +304,15 @@

rateLimiter?.();

// data.description contains the original error.stack
const exceptionHash = hashFromStack(stackParser, data?.description);
const objectId = data?.objectId;

if (exceptionHash == undefined) {
if (objectId == undefined) {
complete();
return;
}

const { add, next } = createCallbackList<FrameVariables[]>(frames => {
cachedFrames.set(exceptionHash, frames);
session.setLocalVarsOnError(objectId, frames);
complete();
});

Expand Down Expand Up @@ -347,8 +350,7 @@
const captureAll = options.captureAllExceptions !== false;

session.configureAndConnect(
(ev, complete) =>
handlePaused(clientOptions.stackParser, ev as InspectorNotification<PausedExceptionEvent>, complete),
(ev, complete) => handlePaused(ev as InspectorNotification<PausedExceptionEvent>, complete),
captureAll,
);

Expand Down Expand Up @@ -377,20 +379,13 @@
},
);
},
processEvent(event: Event): Event {
processEvent(event: Event, hint: EventHint): Event {
if (shouldProcessEvent) {
return addLocalVariablesToEvent(event);
return addLocalVariablesToEvent(event, hint);
}

return event;
},
// These are entirely for testing
_getCachedFramesCount(): number {
return cachedFrames.size;
},
_getFirstCachedFrame(): FrameVariables[] | undefined {
return cachedFrames.values()[0];
},
};
}) satisfies IntegrationFn;

Expand Down
Loading
Loading