feat(node): App Not Responding with stack traces (#9079)

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 <[email protected]>

Author: timfish

packages/node-integration-tests/suites/anr/scenario.js

@@ -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://[email protected]/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);
+});

packages/node-integration-tests/suites/anr/scenario.mjs

@@ -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://[email protected]/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);

packages/node-integration-tests/suites/anr/test.ts

@@ -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();
+    });
+  });
+});

packages/node/src/anr/debugger.ts

@@ -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');
+  };
+}