From 49fc324c01f1c6c3a72d041700c825b770bda030 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Wed, 27 Sep 2023 12:30:18 +0200 Subject: [PATCH 1/6] fix(node): Use spawn rather than fork for ANR --- packages/node/src/anr/index.ts | 28 +++++++++++++--------------- 1 file changed, 13 insertions(+), 15 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index 2d546447ddd7..da06a84ee0dd 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -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 '..'; @@ -99,13 +99,9 @@ function sendEvent(blockedMs: number, frames?: StackFrame[]): void { } 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); } } @@ -117,9 +113,9 @@ function startChildProcess(options: Options): void { env.SENTRY_INSPECT_URL = inspector.url(); } - const child = fork(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 +129,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); } From 41875c1da10daf466169ec7fe924b479f7e6d099 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Wed, 27 Sep 2023 23:31:40 +0200 Subject: [PATCH 2/6] Add support for pm2 --- packages/node/src/anr/index.ts | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index da06a84ee0dd..8efb0480069b 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -105,14 +105,19 @@ function startChildProcess(options: Options): void { } } + process.title = 'sentry-anr-process'; + try { const env = { ...process.env }; + env.SENTRY_ANR_CHILD_PROCESS = 'true'; if (options.captureStackTrace) { inspector.open(); env.SENTRY_INSPECT_URL = inspector.url(); } + log(`Starting child process with execPath:'${process.execPath}' and entryScript'${options.entryScript}'`); + const child = spawn(process.execPath, [options.entryScript], { env, stdio: options.debug ? ['inherit', 'inherit', 'inherit', 'ipc'] : ['ignore', 'ignore', 'ignore', 'ipc'], @@ -219,10 +224,14 @@ function handleChildProcess(options: Options): void { * ``` */ export function enableAnrDetection(options: Partial): Promise { - const isChildProcess = !!process.send; + const isChildProcess = !!process.send && !!process.env.SENTRY_ANR_CHILD_PROCESS; + + // 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, From e8032a836fd144ada607e842969a0c0458eb2a19 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 28 Sep 2023 00:07:40 +0200 Subject: [PATCH 3/6] Correct process.title --- packages/node/src/anr/index.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index 8efb0480069b..b9889171b8a2 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -105,8 +105,6 @@ function startChildProcess(options: Options): void { } } - process.title = 'sentry-anr-process'; - try { const env = { ...process.env }; env.SENTRY_ANR_CHILD_PROCESS = 'true'; @@ -116,7 +114,7 @@ function startChildProcess(options: Options): void { env.SENTRY_INSPECT_URL = inspector.url(); } - log(`Starting child process with execPath:'${process.execPath}' and entryScript'${options.entryScript}'`); + log(`Spawning child process with execPath:'${process.execPath}' and entryScript'${options.entryScript}'`); const child = spawn(process.execPath, [options.entryScript], { env, @@ -156,6 +154,8 @@ function handleChildProcess(options: Options): void { } } + process.title = 'sentry-anr'; + log('Started'); addGlobalEventProcessor(event => { From 916494612b4cb8312f119be225cdc9ff3b84672a Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 28 Sep 2023 11:10:34 +0200 Subject: [PATCH 4/6] Disable tracing and session tracking for ANR child process --- packages/node/src/anr/index.ts | 11 ++++++++--- packages/node/src/sdk.ts | 7 +++++++ 2 files changed, 15 insertions(+), 3 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index b9889171b8a2..53ff85e3ce67 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -200,6 +200,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. * @@ -224,8 +231,6 @@ function handleChildProcess(options: Options): void { * ``` */ export function enableAnrDetection(options: Partial): Promise { - const isChildProcess = !!process.send && !!process.env.SENTRY_ANR_CHILD_PROCESS; - // 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]; @@ -238,7 +243,7 @@ export function enableAnrDetection(options: Partial): Promise { 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(() => { diff --git a/packages/node/src/sdk.ts b/packages/node/src/sdk.ts index 20e8160b7985..7bb0257fc463 100644 --- a/packages/node/src/sdk.ts +++ b/packages/node/src/sdk.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(); From 0fa6e05180678415c580381b74df07b54acfb365 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 28 Sep 2023 11:56:45 +0200 Subject: [PATCH 5/6] Cycle through inspector ports until we find one that available --- packages/node/src/anr/index.ts | 21 +++++++++++++++++++-- 1 file changed, 19 insertions(+), 2 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index 53ff85e3ce67..5c4edd808aa3 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -98,6 +98,24 @@ 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, ...args: unknown[]): void { if (options.debug) { @@ -110,8 +128,7 @@ function startChildProcess(options: Options): void { env.SENTRY_ANR_CHILD_PROCESS = 'true'; if (options.captureStackTrace) { - inspector.open(); - env.SENTRY_INSPECT_URL = inspector.url(); + env.SENTRY_INSPECT_URL = startInspector(); } log(`Spawning child process with execPath:'${process.execPath}' and entryScript'${options.entryScript}'`); From 44cd97aca2171a11ade2b9fd7eaae617e34212c3 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 28 Sep 2023 20:15:12 +0200 Subject: [PATCH 6/6] Test from forked process --- .../suites/anr/{scenario.js => basic.js} | 0 .../suites/anr/{scenario.mjs => basic.mjs} | 0 .../suites/anr/forked.js | 31 +++++++++++++++++++ .../suites/anr/forker.js | 7 +++++ .../node-integration-tests/suites/anr/test.ts | 29 +++++++++++++++-- 5 files changed, 65 insertions(+), 2 deletions(-) rename packages/node-integration-tests/suites/anr/{scenario.js => basic.js} (100%) rename packages/node-integration-tests/suites/anr/{scenario.mjs => basic.mjs} (100%) create mode 100644 packages/node-integration-tests/suites/anr/forked.js create mode 100644 packages/node-integration-tests/suites/anr/forker.js diff --git a/packages/node-integration-tests/suites/anr/scenario.js b/packages/node-integration-tests/suites/anr/basic.js similarity index 100% rename from packages/node-integration-tests/suites/anr/scenario.js rename to packages/node-integration-tests/suites/anr/basic.js diff --git a/packages/node-integration-tests/suites/anr/scenario.mjs b/packages/node-integration-tests/suites/anr/basic.mjs similarity index 100% rename from packages/node-integration-tests/suites/anr/scenario.mjs rename to packages/node-integration-tests/suites/anr/basic.mjs diff --git a/packages/node-integration-tests/suites/anr/forked.js b/packages/node-integration-tests/suites/anr/forked.js new file mode 100644 index 000000000000..3abadc09b9c3 --- /dev/null +++ b/packages/node-integration-tests/suites/anr/forked.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://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); +}); diff --git a/packages/node-integration-tests/suites/anr/forker.js b/packages/node-integration-tests/suites/anr/forker.js new file mode 100644 index 000000000000..c1ac5e1ccd1c --- /dev/null +++ b/packages/node-integration-tests/suites/anr/forker.js @@ -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(); +}); diff --git a/packages/node-integration-tests/suites/anr/test.ts b/packages/node-integration-tests/suites/anr/test.ts index ec820dca9c62..4fd83c0b3205 100644 --- a/packages/node-integration-tests/suites/anr/test.ts +++ b/packages/node-integration-tests/suites/anr/test.ts @@ -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(); + }); + }); });