Skip to content

Commit

Permalink
feat(node): App Not Responding with stack traces (#9079)
Browse files Browse the repository at this point in the history
This PR adds ANR detection for Node via a forked child process. The
child process runs the same entry point as the main app. To ensure that
the main app code does not run in the child process, we use a promise
that only resolves in the main process.

When the `captureStackTrace` option is enabled, debugging is enabled in
the main app process and the child process uses WebSockets to capture
stack traces via the v8 inspector API.

Overhead is expected to be minimal. With no ANR detected, the only
overhead in the main app process is polling the child process over IPC
by default every 50ms. The ANR child process consumes around 50-60 MB or
RAM and simply keeps track of the polling. Once ANR has been detected,
the main process will get paused briefly in the debugger to capture a
stack trace frames. At this point, the event loop has been blocked for
seconds so the debugging overhead can be considered negligible.

Once an ANR event has been reported, the child process exits to prevent
further duplicate events.

```ts
import { init, enableANRDetection } from '@sentry/node';

init({ dsn: "__DSN__" });

// ESM supports top-level await
await enableANRDetection({ captureStackTrace: true });
runApp();

// for CJS you'll need then
enableANRDetection({ captureStackTrace: true }).then(() => {
  runApp();
})
```

Co-authored-by: Abhijeet Prasad <devabhiprasad@gmail.com>
  • Loading branch information
timfish and AbhiPrasad authored Sep 25, 2023
1 parent 50a36bf commit 5a8d4aa
Show file tree
Hide file tree
Showing 10 changed files with 847 additions and 21 deletions.
31 changes: 31 additions & 0 deletions packages/node-integration-tests/suites/anr/scenario.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
const crypto = require('crypto');

const Sentry = require('@sentry/node');

// close both processes after 5 seconds
setTimeout(() => {
process.exit();
}, 5000);

Sentry.init({
dsn: 'https://public@dsn.ingest.sentry.io/1337',
release: '1.0',
beforeSend: event => {
// eslint-disable-next-line no-console
console.log(JSON.stringify(event));
},
});

Sentry.enableAnrDetection({ captureStackTrace: true, anrThreshold: 200, debug: true }).then(() => {
function longWork() {
for (let i = 0; i < 100; i++) {
const salt = crypto.randomBytes(128).toString('base64');
// eslint-disable-next-line no-unused-vars
const hash = crypto.pbkdf2Sync('myPassword', salt, 10000, 512, 'sha512');
}
}

setTimeout(() => {
longWork();
}, 1000);
});
31 changes: 31 additions & 0 deletions packages/node-integration-tests/suites/anr/scenario.mjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
import * as crypto from 'crypto';

import * as Sentry from '@sentry/node';

// close both processes after 5 seconds
setTimeout(() => {
process.exit();
}, 5000);

Sentry.init({
dsn: 'https://public@dsn.ingest.sentry.io/1337',
release: '1.0',
beforeSend: event => {
// eslint-disable-next-line no-console
console.log(JSON.stringify(event));
},
});

await Sentry.enableAnrDetection({ captureStackTrace: true, anrThreshold: 200, debug: true });

function longWork() {
for (let i = 0; i < 100; i++) {
const salt = crypto.randomBytes(128).toString('base64');
// eslint-disable-next-line no-unused-vars
const hash = crypto.pbkdf2Sync('myPassword', salt, 10000, 512, 'sha512');
}
}

setTimeout(() => {
longWork();
}, 1000);
57 changes: 57 additions & 0 deletions packages/node-integration-tests/suites/anr/test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,57 @@
import type { Event } from '@sentry/node';
import { parseSemver } from '@sentry/utils';
import * as childProcess from 'child_process';
import * as path from 'path';

const NODE_VERSION = parseSemver(process.versions.node).major || 0;

describe('should report ANR when event loop blocked', () => {
test('CJS', done => {
// The stack trace is different when node < 12
const testFramesDetails = NODE_VERSION >= 12;

expect.assertions(testFramesDetails ? 6 : 4);

const testScriptPath = path.resolve(__dirname, 'scenario.js');

childProcess.exec(`node ${testScriptPath}`, { encoding: 'utf8' }, (_, stdout) => {
const event = JSON.parse(stdout) as Event;

expect(event.exception?.values?.[0].mechanism).toEqual({ type: 'ANR' });
expect(event.exception?.values?.[0].type).toEqual('ApplicationNotResponding');
expect(event.exception?.values?.[0].value).toEqual('Application Not Responding for at least 200 ms');
expect(event.exception?.values?.[0].stacktrace?.frames?.length).toBeGreaterThan(4);

if (testFramesDetails) {
expect(event.exception?.values?.[0].stacktrace?.frames?.[2].function).toEqual('?');
expect(event.exception?.values?.[0].stacktrace?.frames?.[3].function).toEqual('longWork');
}

done();
});
});

test('ESM', done => {
if (NODE_VERSION < 14) {
done();
return;
}

expect.assertions(6);

const testScriptPath = path.resolve(__dirname, 'scenario.mjs');

childProcess.exec(`node ${testScriptPath}`, { encoding: 'utf8' }, (_, stdout) => {
const event = JSON.parse(stdout) as Event;

expect(event.exception?.values?.[0].mechanism).toEqual({ type: 'ANR' });
expect(event.exception?.values?.[0].type).toEqual('ApplicationNotResponding');
expect(event.exception?.values?.[0].value).toEqual('Application Not Responding for at least 200 ms');
expect(event.exception?.values?.[0].stacktrace?.frames?.length).toBeGreaterThan(4);
expect(event.exception?.values?.[0].stacktrace?.frames?.[2].function).toEqual('?');
expect(event.exception?.values?.[0].stacktrace?.frames?.[3].function).toEqual('longWork');

done();
});
});
});
95 changes: 95 additions & 0 deletions packages/node/src/anr/debugger.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,95 @@
import type { StackFrame } from '@sentry/types';
import { dropUndefinedKeys, filenameIsInApp } from '@sentry/utils';
import type { Debugger } from 'inspector';

import { getModuleFromFilename } from '../module';
import { createWebSocketClient } from './websocket';

/**
* Converts Debugger.CallFrame to Sentry StackFrame
*/
function callFrameToStackFrame(
frame: Debugger.CallFrame,
filenameFromScriptId: (id: string) => string | undefined,
): StackFrame {
const filename = filenameFromScriptId(frame.location.scriptId)?.replace(/^file:\/\//, '');

// CallFrame row/col are 0 based, whereas StackFrame are 1 based
const colno = frame.location.columnNumber ? frame.location.columnNumber + 1 : undefined;
const lineno = frame.location.lineNumber ? frame.location.lineNumber + 1 : undefined;

return dropUndefinedKeys({
filename,
module: getModuleFromFilename(filename),
function: frame.functionName || '?',
colno,
lineno,
in_app: filename ? filenameIsInApp(filename) : undefined,
});
}

// The only messages we care about
type DebugMessage =
| {
method: 'Debugger.scriptParsed';
params: Debugger.ScriptParsedEventDataType;
}
| { method: 'Debugger.paused'; params: Debugger.PausedEventDataType };

/**
* Wraps a websocket connection with the basic logic of the Node debugger protocol.
* @param url The URL to connect to
* @param onMessage A callback that will be called with each return message from the debugger
* @returns A function that can be used to send commands to the debugger
*/
async function webSocketDebugger(
url: string,
onMessage: (message: DebugMessage) => void,
): Promise<(method: string, params?: unknown) => void> {
let id = 0;
const webSocket = await createWebSocketClient(url);

webSocket.on('message', (data: Buffer) => {
const message = JSON.parse(data.toString()) as DebugMessage;
onMessage(message);
});

return (method: string, params?: unknown) => {
webSocket.send(JSON.stringify({ id: id++, method, params }));
};
}

/**
* Captures stack traces from the Node debugger.
* @param url The URL to connect to
* @param callback A callback that will be called with the stack frames
* @returns A function that triggers the debugger to pause and capture a stack trace
*/
export async function captureStackTrace(url: string, callback: (frames: StackFrame[]) => void): Promise<() => void> {
// Collect scriptId -> url map so we can look up the filenames later
const scripts = new Map<string, string>();

const sendCommand = await webSocketDebugger(url, message => {
if (message.method === 'Debugger.scriptParsed') {
scripts.set(message.params.scriptId, message.params.url);
} else if (message.method === 'Debugger.paused') {
// copy the frames
const callFrames = [...message.params.callFrames];
// and resume immediately!
sendCommand('Debugger.resume');
sendCommand('Debugger.disable');

const frames = callFrames
.map(frame => callFrameToStackFrame(frame, id => scripts.get(id)))
// Sentry expects the frames to be in the opposite order
.reverse();

callback(frames);
}
});

return () => {
sendCommand('Debugger.enable');
sendCommand('Debugger.pause');
};
}
Loading

0 comments on commit 5a8d4aa

Please sign in to comment.