fix(node): Fixes and improvements to ANR detection (#9128)

Author: timfish

packages/node-integration-tests/suites/anr/scenario.js renamed to packages/node-integration-tests/suites/anr/basic.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 renamed to packages/node-integration-tests/suites/anr/basic.mjs

@@ -0,0 +1,7 @@
+const { fork } = require('child_process');
+const { join } = require('path');
+
+const child = fork(join(__dirname, 'forked.js'), { stdio: 'inherit' });
+child.on('exit', () => {
+  process.exit();
+});

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

@@ -12,7 +12,7 @@ describe('should report ANR when event loop blocked', () => {
 
     expect.assertions(testFramesDetails ? 6 : 4);
 
-    const testScriptPath = path.resolve(__dirname, 'scenario.js');
+    const testScriptPath = path.resolve(__dirname, 'basic.js');
 
     childProcess.exec(`node ${testScriptPath}`, { encoding: 'utf8' }, (_, stdout) => {
       const event = JSON.parse(stdout) as Event;
@@ -39,7 +39,7 @@ describe('should report ANR when event loop blocked', () => {
 
     expect.assertions(6);
 
-    const testScriptPath = path.resolve(__dirname, 'scenario.mjs');
+    const testScriptPath = path.resolve(__dirname, 'basic.mjs');
 
     childProcess.exec(`node ${testScriptPath}`, { encoding: 'utf8' }, (_, stdout) => {
       const event = JSON.parse(stdout) as Event;
@@ -54,4 +54,29 @@ describe('should report ANR when event loop blocked', () => {
       done();
     });
   });
+
+  test('from forked process', done => {
+    // The stack trace is different when node < 12
+    const testFramesDetails = NODE_VERSION >= 12;
+
+    expect.assertions(testFramesDetails ? 6 : 4);
+
+    const testScriptPath = path.resolve(__dirname, 'forker.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();
+    });
+  });
 });

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

@@ -1,6 +1,6 @@
 import type { Event, StackFrame } from '@sentry/types';
 import { logger } from '@sentry/utils';
-import { fork } from 'child_process';
+import { spawn } from 'child_process';
 import * as inspector from 'inspector';
 
 import { addGlobalEventProcessor, captureEvent, flush } from '..';
@@ -98,28 +98,44 @@ function sendEvent(blockedMs: number, frames?: StackFrame[]): void {
   });
 }
 
+/**
+ * Starts the node debugger and returns the inspector url.
+ *
+ * When inspector.url() returns undefined, it means the port is already in use so we try the next port.
+ */
+function startInspector(startPort: number = 9229): string | undefined {
+  let inspectorUrl: string | undefined = undefined;
+  let port = startPort;
+
+  while (inspectorUrl === undefined && port < startPort + 100) {
+    inspector.open(port);
+    inspectorUrl = inspector.url();
+    port++;
+  }
+
+  return inspectorUrl;
+}
+
 function startChildProcess(options: Options): void {
-  function log(message: string, err?: unknown): void {
+  function log(message: string, ...args: unknown[]): void {
     if (options.debug) {
-      if (err) {
-        logger.log(`[ANR] ${message}`, err);
-      } else {
-        logger.log(`[ANR] ${message}`);
-      }
+      logger.log(`[ANR] ${message}`, ...args);
     }
   }
 
   try {
     const env = { ...process.env };
+    env.SENTRY_ANR_CHILD_PROCESS = 'true';
 
     if (options.captureStackTrace) {
-      inspector.open();
-      env.SENTRY_INSPECT_URL = inspector.url();
+      env.SENTRY_INSPECT_URL = startInspector();
     }
 
-    const child = fork(options.entryScript, {
+    log(`Spawning child process with execPath:'${process.execPath}' and entryScript'${options.entryScript}'`);
+
+    const child = spawn(process.execPath, [options.entryScript], {
       env,
-      stdio: options.debug ? 'inherit' : 'ignore',
+      stdio: options.debug ? ['inherit', 'inherit', 'inherit', 'ipc'] : ['ignore', 'ignore', 'ignore', 'ipc'],
     });
     // The child process should not keep the main process alive
     child.unref();
@@ -133,14 +149,16 @@ function startChildProcess(options: Options): void {
       }
     }, options.pollInterval);
 
-    const end = (err: unknown): void => {
-      clearInterval(timer);
-      log('Child process ended', err);
+    const end = (type: string): ((...args: unknown[]) => void) => {
+      return (...args): void => {
+        clearInterval(timer);
+        log(`Child process ${type}`, ...args);
+      };
     };
 
-    child.on('error', end);
-    child.on('disconnect', end);
-    child.on('exit', end);
+    child.on('error', end('error'));
+    child.on('disconnect', end('disconnect'));
+    child.on('exit', end('exit'));
   } catch (e) {
     log('Failed to start child process', e);
   }
@@ -153,6 +171,8 @@ function handleChildProcess(options: Options): void {
     }
   }
 
+  process.title = 'sentry-anr';
+
   log('Started');
 
   addGlobalEventProcessor(event => {
@@ -197,6 +217,13 @@ function handleChildProcess(options: Options): void {
   });
 }
 
+/**
+ * Returns true if the current process is an ANR child process.
+ */
+export function isAnrChildProcess(): boolean {
+  return !!process.send && !!process.env.SENTRY_ANR_CHILD_PROCESS;
+}
+
 /**
  * **Note** This feature is still in beta so there may be breaking changes in future releases.
  *
@@ -221,17 +248,19 @@ function handleChildProcess(options: Options): void {
  * ```
  */
 export function enableAnrDetection(options: Partial<Options>): Promise<void> {
-  const isChildProcess = !!process.send;
+  // When pm2 runs the script in cluster mode, process.argv[1] is the pm2 script and process.env.pm_exec_path is the
+  // path to the entry script
+  const entryScript = options.entryScript || process.env.pm_exec_path || process.argv[1];
 
   const anrOptions: Options = {
-    entryScript: options.entryScript || process.argv[1],
+    entryScript,
     pollInterval: options.pollInterval || DEFAULT_INTERVAL,
     anrThreshold: options.anrThreshold || DEFAULT_HANG_THRESHOLD,
     captureStackTrace: !!options.captureStackTrace,
     debug: !!options.debug,
   };
 
-  if (isChildProcess) {
+  if (isAnrChildProcess()) {
     handleChildProcess(anrOptions);
     // In the child process, the promise never resolves which stops the app code from running
     return new Promise<void>(() => {

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

@@ -15,6 +15,7 @@ import {
   tracingContextFromHeaders,
 } from '@sentry/utils';
 
+import { isAnrChildProcess } from './anr';
 import { setNodeAsyncContextStrategy } from './async';
 import { NodeClient } from './client';
 import {
@@ -110,7 +111,13 @@ export const defaultIntegrations = [
  *
  * @see {@link NodeOptions} for documentation on configuration options.
  */
+// eslint-disable-next-line complexity
 export function init(options: NodeOptions = {}): void {
+  if (isAnrChildProcess()) {
+    options.autoSessionTracking = false;
+    options.tracesSampleRate = 0;
+  }
+
   const carrier = getMainCarrier();
 
   setNodeAsyncContextStrategy();