From 581822a5b474014d6582b30e38051f00c32fb03f Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 00:44:04 +0100 Subject: [PATCH 01/12] feat(node): App Not Responding with stack traces --- .../suites/anr/scenario.js | 31 ++ .../node-integration-tests/suites/anr/test.ts | 21 + packages/node/src/anr/debugger.ts | 95 +++++ packages/node/src/anr/index.ts | 191 ++++++++++ packages/node/src/anr/websocket.ts | 359 ++++++++++++++++++ packages/node/src/index.ts | 1 + packages/types/src/mechanism.ts | 2 +- packages/utils/src/node-stack-trace.ts | 43 ++- packages/utils/src/stacktrace.ts | 4 +- 9 files changed, 726 insertions(+), 21 deletions(-) create mode 100644 packages/node-integration-tests/suites/anr/scenario.js create mode 100644 packages/node-integration-tests/suites/anr/test.ts create mode 100644 packages/node/src/anr/debugger.ts create mode 100644 packages/node/src/anr/index.ts create mode 100644 packages/node/src/anr/websocket.ts diff --git a/packages/node-integration-tests/suites/anr/scenario.js b/packages/node-integration-tests/suites/anr/scenario.js new file mode 100644 index 000000000000..a13fc7f95b67 --- /dev/null +++ b/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://public@dsn.ingest.sentry.io/1337', + release: '1.0', + beforeSend: event => { + // eslint-disable-next-line no-console + console.log(JSON.stringify(event)); + }, +}); + +Sentry.arnWatchdog({ captureStackTrace: true, hungThreshold: 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/test.ts b/packages/node-integration-tests/suites/anr/test.ts new file mode 100644 index 000000000000..7754cf039ada --- /dev/null +++ b/packages/node-integration-tests/suites/anr/test.ts @@ -0,0 +1,21 @@ +import type { Event } from '@sentry/node'; +import * as childProcess from 'child_process'; +import * as path from 'path'; + +test('should report ANR when event loop blocked', done => { + expect.assertions(5); + + 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?.[2].function).toEqual('?'); + expect(event.exception?.values?.[0].stacktrace?.frames?.[3].function).toEqual('longWork'); + + done(); + }); +}); diff --git a/packages/node/src/anr/debugger.ts b/packages/node/src/anr/debugger.ts new file mode 100644 index 000000000000..4d4a2799fa64 --- /dev/null +++ b/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(); + + 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'); + }; +} diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts new file mode 100644 index 000000000000..38b0e4ff8b40 --- /dev/null +++ b/packages/node/src/anr/index.ts @@ -0,0 +1,191 @@ +import type { Event, StackFrame } from '@sentry/types'; +import { fork } from 'child_process'; +import * as inspector from 'inspector'; + +import { addGlobalEventProcessor, captureEvent, flush } from '..'; +import { captureStackTrace } from './debugger'; + +const DEFAULT_INTERVAL = 50; +const DEFAULT_HANG_THRESHOLD = 5000; + +interface Options { + /** + * The app entry script. This is used to run the same script as the child process. + * + * Defaults to `process.argv[1]`. + */ + entryScript: string; + /** + * Interval to send alive messages to the child process. + * + * Defaults to 50ms. + */ + pollInterval: number; + /** + * Threshold in milliseconds to trigger an ANR event. + * + * Defaults to 1000ms. + */ + hungThreshold: number; + /** + * Whether to capture a stack trace when the ANR event is triggered. + * + * Defaults to `false`. + * + * This uses the node debugger which enables the inspector API and opens the required ports. + */ + captureStackTrace: boolean; + /** + * Log debug information. + */ + debug: boolean; +} + +function watchdogTimer(pollInterval: number, hungThreshold: number, callback: () => void): () => void { + let lastPoll = process.hrtime(); + let triggered = false; + + setInterval(() => { + const [seconds, nanoSeconds] = process.hrtime(lastPoll); + const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); + + if (triggered === false && diffMs > pollInterval + hungThreshold) { + triggered = true; + callback(); + } + + if (diffMs < pollInterval + hungThreshold) { + triggered = false; + } + }, 10).unref(); + + return () => { + lastPoll = process.hrtime(); + }; +} + +function sendEvent(blockedMs: number, frames?: StackFrame[]): void { + const event: Event = { + level: 'error', + exception: { + values: [ + { + type: 'ApplicationNotResponding', + value: `Application Not Responding for at least ${blockedMs} ms`, + stacktrace: { frames }, + mechanism: { + // This ensures the UI doesn't say 'Crashed in' for the stack trace + type: 'ANR', + }, + }, + ], + }, + }; + + captureEvent(event); + + void flush(3000).then(() => { + // We only capture one event to avoid spamming users with errors + process.exit(); + }); +} + +function startChildProcess(options: Options): void { + const env = { ...process.env }; + + if (options.captureStackTrace) { + inspector.open(); + env.SENTRY_INSPECT_URL = inspector.url(); + } + + const child = fork(options.entryScript, { + env, + stdio: options.debug ? 'inherit' : 'ignore', + }); + // The child process should not keep the main process alive + child.unref(); + + const timer = setInterval(() => { + try { + // message the child process to tell it the main event loop is still running + child.send('ping'); + } catch (_) { + // + } + }, options.pollInterval); + + child.on('error', () => { + clearTimeout(timer); + }); + child.on('disconnect', () => { + clearTimeout(timer); + }); + child.on('exit', () => { + clearTimeout(timer); + }); +} + +function handleChildProcess(options: Options): void { + addGlobalEventProcessor(event => { + // Strip sdkProcessingMetadata from all child process events to remove trace info + delete event.sdkProcessingMetadata; + return event; + }); + + let debuggerPause: Promise<() => void> | undefined; + + // if attachStackTrace is enabled, we'll have a debugger url to connect to + if (process.env.SENTRY_INSPECT_URL) { + debuggerPause = captureStackTrace(process.env.SENTRY_INSPECT_URL, frames => { + sendEvent(options.hungThreshold, frames); + }); + } + + async function watchdogTimeout(): Promise { + const pauseAndCapture = await debuggerPause; + + if (pauseAndCapture) { + pauseAndCapture(); + } else { + sendEvent(options.hungThreshold); + } + } + + const ping = watchdogTimer(options.pollInterval, options.hungThreshold, watchdogTimeout); + + process.on('message', () => { + ping(); + }); +} + +/** + * Create a watchdog process to report Application Not Responding (ANR) errors. + * + * It's important to await on the returned promise before your app code to ensure this code does not run in the watchdog + * process. + * + * + */ +export function arnWatchdog(options: Partial): Promise { + const isChildProcess = !!process.send; + + const anrOptions: Options = { + entryScript: options.entryScript || process.argv[1], + pollInterval: options.pollInterval || DEFAULT_INTERVAL, + hungThreshold: options.hungThreshold || DEFAULT_HANG_THRESHOLD, + captureStackTrace: !!options.captureStackTrace, + debug: !!options.debug, + }; + + if (isChildProcess) { + handleChildProcess(anrOptions); + // In the child process, the promise never resolves which stops the app code from running + return new Promise(() => { + // Never resolve + }); + } else { + startChildProcess(anrOptions); + // In the main process, the promise resolves immediately + return Promise.resolve(); + } +} diff --git a/packages/node/src/anr/websocket.ts b/packages/node/src/anr/websocket.ts new file mode 100644 index 000000000000..9faa90bcfd1c --- /dev/null +++ b/packages/node/src/anr/websocket.ts @@ -0,0 +1,359 @@ +/* eslint-disable no-bitwise */ +/** + * A simple WebSocket client implementation copied from Rome before being modified for our use: + * https://github.com/jeremyBanks/rome/tree/b034dd22d5f024f87c50eef2872e22b3ad48973a/packages/%40romejs/codec-websocket + * + * Original license: + * + * MIT License + * + * Copyright (c) Facebook, Inc. and its affiliates. + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in all + * copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, + * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE + * SOFTWARE. + */ + +import * as crypto from 'crypto'; +import { EventEmitter } from 'events'; +import * as http from 'http'; +import type { Socket } from 'net'; +import * as url from 'url'; + +type BuildFrameOpts = { + opcode: number; + fin: boolean; + data: Buffer; +}; + +type Frame = { + fin: boolean; + opcode: number; + mask: undefined | Buffer; + payload: Buffer; + payloadLength: number; +}; + +const OPCODES = { + CONTINUATION: 0, + TEXT: 1, + BINARY: 2, + TERMINATE: 8, + PING: 9, + PONG: 10, +}; + +const GUID = '258EAFA5-E914-47DA-95CA-C5AB0DC85B11'; + +function isCompleteFrame(frame: Frame): boolean { + return Buffer.byteLength(frame.payload) >= frame.payloadLength; +} + +function unmaskPayload(payload: Buffer, mask: undefined | Buffer, offset: number): Buffer { + if (mask === undefined) { + return payload; + } + + for (let i = 0; i < payload.length; i++) { + payload[i] ^= mask[(offset + i) & 3]; + } + + return payload; +} + +function buildFrame(opts: BuildFrameOpts): Buffer { + const { opcode, fin, data } = opts; + + let offset = 6; + let dataLength = data.length; + + if (dataLength >= 65_536) { + offset += 8; + dataLength = 127; + } else if (dataLength > 125) { + offset += 2; + dataLength = 126; + } + + const head = Buffer.allocUnsafe(offset); + + head[0] = fin ? opcode | 128 : opcode; + head[1] = dataLength; + + if (dataLength === 126) { + head.writeUInt16BE(data.length, 2); + } else if (dataLength === 127) { + head.writeUInt32BE(0, 2); + head.writeUInt32BE(data.length, 6); + } + + const mask = crypto.randomBytes(4); + head[1] |= 128; + head[offset - 4] = mask[0]; + head[offset - 3] = mask[1]; + head[offset - 2] = mask[2]; + head[offset - 1] = mask[3]; + + const masked = Buffer.alloc(dataLength); + for (let i = 0; i < dataLength; ++i) { + masked[i] = data[i] ^ mask[i & 3]; + } + + return Buffer.concat([head, masked]); +} + +function parseFrame(buffer: Buffer): Frame { + const firstByte = buffer.readUInt8(0); + const isFinalFrame: boolean = Boolean((firstByte >>> 7) & 1); + const opcode: number = firstByte & 15; + + const secondByte: number = buffer.readUInt8(1); + const isMasked: boolean = Boolean((secondByte >>> 7) & 1); + + // Keep track of our current position as we advance through the buffer + let currentOffset = 2; + let payloadLength = secondByte & 127; + if (payloadLength > 125) { + if (payloadLength === 126) { + payloadLength = buffer.readUInt16BE(currentOffset); + currentOffset += 2; + } else if (payloadLength === 127) { + const leftPart = buffer.readUInt32BE(currentOffset); + currentOffset += 4; + + // The maximum safe integer in JavaScript is 2^53 - 1. An error is returned + + // if payload length is greater than this number. + if (leftPart >= Number.MAX_SAFE_INTEGER) { + throw new Error('Unsupported WebSocket frame: payload length > 2^53 - 1'); + } + + const rightPart = buffer.readUInt32BE(currentOffset); + currentOffset += 4; + + payloadLength = leftPart * Math.pow(2, 32) + rightPart; + } else { + throw new Error('Unknown payload length'); + } + } + + // Get the masking key if one exists + let mask; + if (isMasked) { + mask = buffer.slice(currentOffset, currentOffset + 4); + currentOffset += 4; + } + + const payload = unmaskPayload(buffer.slice(currentOffset), mask, 0); + + return { + fin: isFinalFrame, + opcode, + mask, + payload, + payloadLength, + }; +} + +function createKey(key: string): string { + return crypto.createHash('sha1').update(`${key}${GUID}`).digest('base64'); +} + +class WebSocketInterface extends EventEmitter { + private _alive: boolean; + private _incompleteFrame: undefined | Frame; + private _unfinishedFrame: undefined | Frame; + private _socket: Socket; + + public constructor(socket: Socket) { + super(); + // When a frame is set here then any additional continuation frames payloads will be appended + this._unfinishedFrame = undefined; + + // When a frame is set here, all additional chunks will be appended until we reach the correct payloadLength + this._incompleteFrame = undefined; + + this._socket = socket; + this._alive = true; + + socket.on('data', buff => { + this._addBuffer(buff); + }); + + socket.on('error', (err: NodeJS.ErrnoException) => { + if (err.code === 'ECONNRESET') { + this.emit('close'); + } else { + this.emit('error'); + } + }); + + socket.on('close', () => { + this.end(); + }); + } + + public end(): void { + if (!this._alive) { + return; + } + + this._alive = false; + this.emit('close'); + this._socket.end(); + } + + public send(buff: string): void { + this._sendFrame({ + opcode: OPCODES.TEXT, + fin: true, + data: Buffer.from(buff), + }); + } + + private _sendFrame(frameOpts: BuildFrameOpts): void { + this._socket.write(buildFrame(frameOpts)); + } + + private _completeFrame(frame: Frame): void { + // If we have an unfinished frame then only allow continuations + const { _unfinishedFrame: unfinishedFrame } = this; + if (unfinishedFrame !== undefined) { + if (frame.opcode === OPCODES.CONTINUATION) { + unfinishedFrame.payload = Buffer.concat([ + unfinishedFrame.payload, + unmaskPayload(frame.payload, unfinishedFrame.mask, unfinishedFrame.payload.length), + ]); + + if (frame.fin) { + this._unfinishedFrame = undefined; + this._completeFrame(unfinishedFrame); + } + return; + } else { + // Silently ignore the previous frame... + this._unfinishedFrame = undefined; + } + } + + if (frame.fin) { + if (frame.opcode === OPCODES.PING) { + this._sendFrame({ + opcode: OPCODES.PONG, + fin: true, + data: frame.payload, + }); + } else { + // Trim off any excess payload + let excess; + if (frame.payload.length > frame.payloadLength) { + excess = frame.payload.slice(frame.payloadLength); + frame.payload = frame.payload.slice(0, frame.payloadLength); + } + + this.emit('message', frame.payload); + + if (excess !== undefined) { + this._addBuffer(excess); + } + } + } else { + this._unfinishedFrame = frame; + } + } + + private _addBufferToIncompleteFrame(incompleteFrame: Frame, buff: Buffer): void { + incompleteFrame.payload = Buffer.concat([ + incompleteFrame.payload, + unmaskPayload(buff, incompleteFrame.mask, incompleteFrame.payload.length), + ]); + + if (isCompleteFrame(incompleteFrame)) { + this._incompleteFrame = undefined; + this._completeFrame(incompleteFrame); + } + } + + private _addBuffer(buff: Buffer): void { + // Check if we're still waiting for the rest of a payload + const { _incompleteFrame: incompleteFrame } = this; + if (incompleteFrame !== undefined) { + this._addBufferToIncompleteFrame(incompleteFrame, buff); + return; + } + + const frame = parseFrame(buff); + + if (isCompleteFrame(frame)) { + // Frame has been completed! + this._completeFrame(frame); + } else { + this._incompleteFrame = frame; + } + } +} + +/** + * Creates a WebSocket client + */ +export async function createWebSocketClient(rawUrl: string): Promise { + const parts = url.parse(rawUrl); + + return new Promise((resolve, reject) => { + const key = crypto.randomBytes(16).toString('base64'); + const digest = createKey(key); + + const req = http.request({ + hostname: parts.hostname, + port: parts.port, + path: parts.path, + method: 'GET', + headers: { + Connection: 'Upgrade', + Upgrade: 'websocket', + 'Sec-WebSocket-Key': key, + 'Sec-WebSocket-Version': '13', + }, + }); + + req.on('response', (res: http.IncomingMessage) => { + if (res.statusCode && res.statusCode >= 400) { + process.stderr.write(`Unexpected HTTP code: ${res.statusCode}\n`); + res.pipe(process.stderr); + } else { + res.pipe(process.stderr); + } + }); + + req.on('upgrade', (res: http.IncomingMessage, socket: Socket) => { + if (res.headers['sec-websocket-accept'] !== digest) { + socket.end(); + reject(new Error(`Digest mismatch ${digest} !== ${res.headers['sec-websocket-accept']}`)); + return; + } + + const client = new WebSocketInterface(socket); + resolve(client); + }); + + req.on('error', err => { + reject(err); + }); + + req.end(); + }); +} diff --git a/packages/node/src/index.ts b/packages/node/src/index.ts index c7d93ef16463..7e12661cfc76 100644 --- a/packages/node/src/index.ts +++ b/packages/node/src/index.ts @@ -71,6 +71,7 @@ export { defaultIntegrations, init, defaultStackParser, getSentryRelease } from export { addRequestDataToEvent, DEFAULT_USER_INCLUDES, extractRequestData } from './requestdata'; export { deepReadDirSync } from './utils'; export { getModuleFromFilename } from './module'; +export { arnWatchdog } from './anr'; import { Integrations as CoreIntegrations } from '@sentry/core'; diff --git a/packages/types/src/mechanism.ts b/packages/types/src/mechanism.ts index 0f2adf98ed24..9d3dc86e7382 100644 --- a/packages/types/src/mechanism.ts +++ b/packages/types/src/mechanism.ts @@ -13,7 +13,7 @@ export interface Mechanism { * it hits the global error/rejection handlers, whether through explicit handling by the user or auto instrumentation. * Converted to a tag on ingest and used in various ways in the UI. */ - handled: boolean; + handled?: boolean; /** * Arbitrary data to be associated with the mechanism (for example, errors coming from event handlers include the diff --git a/packages/utils/src/node-stack-trace.ts b/packages/utils/src/node-stack-trace.ts index 00b02b0fee35..43db209a5fc5 100644 --- a/packages/utils/src/node-stack-trace.ts +++ b/packages/utils/src/node-stack-trace.ts @@ -25,6 +25,29 @@ import type { StackLineParserFn } from '@sentry/types'; export type GetModuleFn = (filename: string | undefined) => string | undefined; +/** + * Does this filename look like it's part of the app code? + */ +export function filenameIsInApp(filename: string, isNative: boolean = false): boolean { + const isInternal = + isNative || + (filename && + // It's not internal if it's an absolute linux path + !filename.startsWith('/') && + // It's not internal if it's an absolute windows path + !filename.includes(':\\') && + // It's not internal if the path is starting with a dot + !filename.startsWith('.') && + // It's not internal if the frame has a protocol. In node, this is usually the case if the file got pre-processed with a bundler like webpack + !filename.match(/^[a-zA-Z]([a-zA-Z0-9.\-+])*:\/\//)); // Schema from: https://stackoverflow.com/a/3641782 + + // in_app is all that's not an internal Node function or a module within node_modules + // note that isNative appears to return true even for node core libraries + // see https://github.com/getsentry/raven-node/issues/176 + + return !isInternal && filename !== undefined && !filename.includes('node_modules/'); +} + /** Node Stack line parser */ // eslint-disable-next-line complexity export function node(getModule?: GetModuleFn): StackLineParserFn { @@ -84,31 +107,13 @@ export function node(getModule?: GetModuleFn): StackLineParserFn { filename = lineMatch[5]; } - const isInternal = - isNative || - (filename && - // It's not internal if it's an absolute linux path - !filename.startsWith('/') && - // It's not internal if it's an absolute windows path - !filename.includes(':\\') && - // It's not internal if the path is starting with a dot - !filename.startsWith('.') && - // It's not internal if the frame has a protocol. In node, this is usually the case if the file got pre-processed with a bundler like webpack - !filename.match(/^[a-zA-Z]([a-zA-Z0-9.\-+])*:\/\//)); // Schema from: https://stackoverflow.com/a/3641782 - - // in_app is all that's not an internal Node function or a module within node_modules - // note that isNative appears to return true even for node core libraries - // see https://github.com/getsentry/raven-node/issues/176 - - const in_app = !isInternal && filename !== undefined && !filename.includes('node_modules/'); - return { filename, module: getModule ? getModule(filename) : undefined, function: functionName, lineno: parseInt(lineMatch[3], 10) || undefined, colno: parseInt(lineMatch[4], 10) || undefined, - in_app, + in_app: filenameIsInApp(filename, isNative), }; } diff --git a/packages/utils/src/stacktrace.ts b/packages/utils/src/stacktrace.ts index ac9f2159221d..917b46daa5d1 100644 --- a/packages/utils/src/stacktrace.ts +++ b/packages/utils/src/stacktrace.ts @@ -1,7 +1,9 @@ import type { StackFrame, StackLineParser, StackParser } from '@sentry/types'; import type { GetModuleFn } from './node-stack-trace'; -import { node } from './node-stack-trace'; +import { filenameIsInApp, node } from './node-stack-trace'; + +export { filenameIsInApp }; const STACKTRACE_FRAME_LIMIT = 50; // Used to sanitize webpack (error: *) wrapped stack errors From b5aa74ae6509599a0be0924c0054a926ab8415bb Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 01:07:01 +0100 Subject: [PATCH 02/12] Don't bother unref'ing timer --- packages/node/src/anr/index.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index 38b0e4ff8b40..8fd0e0fa252f 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -57,7 +57,7 @@ function watchdogTimer(pollInterval: number, hungThreshold: number, callback: () if (diffMs < pollInterval + hungThreshold) { triggered = false; } - }, 10).unref(); + }, 10); return () => { lastPoll = process.hrtime(); From c9025da1fedba88ff8c42d2afad7eee56d0c6ce4 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 02:13:19 +0100 Subject: [PATCH 03/12] Dont test stack frame detail on node < 12 --- .../node-integration-tests/suites/anr/test.ts | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/packages/node-integration-tests/suites/anr/test.ts b/packages/node-integration-tests/suites/anr/test.ts index 7754cf039ada..d43330b8567b 100644 --- a/packages/node-integration-tests/suites/anr/test.ts +++ b/packages/node-integration-tests/suites/anr/test.ts @@ -1,9 +1,15 @@ 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; + test('should report ANR when event loop blocked', done => { - expect.assertions(5); + // 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'); @@ -13,8 +19,12 @@ test('should report ANR when event loop blocked', done => { 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?.[2].function).toEqual('?'); - expect(event.exception?.values?.[0].stacktrace?.frames?.[3].function).toEqual('longWork'); + 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(); }); From e97376ba4b9bb4d11c767345f15e5d288d31719c Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 13:30:31 +0100 Subject: [PATCH 04/12] rename option --- packages/node/src/anr/index.ts | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index 8fd0e0fa252f..affdfef85668 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -24,9 +24,9 @@ interface Options { /** * Threshold in milliseconds to trigger an ANR event. * - * Defaults to 1000ms. + * Defaults to 5000ms. */ - hungThreshold: number; + anrThreshold: number; /** * Whether to capture a stack trace when the ANR event is triggered. * @@ -41,7 +41,7 @@ interface Options { debug: boolean; } -function watchdogTimer(pollInterval: number, hungThreshold: number, callback: () => void): () => void { +function watchdogTimer(pollInterval: number, anrThreshold: number, callback: () => void): () => void { let lastPoll = process.hrtime(); let triggered = false; @@ -49,12 +49,12 @@ function watchdogTimer(pollInterval: number, hungThreshold: number, callback: () const [seconds, nanoSeconds] = process.hrtime(lastPoll); const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); - if (triggered === false && diffMs > pollInterval + hungThreshold) { + if (triggered === false && diffMs > pollInterval + anrThreshold) { triggered = true; callback(); } - if (diffMs < pollInterval + hungThreshold) { + if (diffMs < pollInterval + anrThreshold) { triggered = false; } }, 10); @@ -137,7 +137,7 @@ function handleChildProcess(options: Options): void { // if attachStackTrace is enabled, we'll have a debugger url to connect to if (process.env.SENTRY_INSPECT_URL) { debuggerPause = captureStackTrace(process.env.SENTRY_INSPECT_URL, frames => { - sendEvent(options.hungThreshold, frames); + sendEvent(options.anrThreshold, frames); }); } @@ -147,11 +147,11 @@ function handleChildProcess(options: Options): void { if (pauseAndCapture) { pauseAndCapture(); } else { - sendEvent(options.hungThreshold); + sendEvent(options.anrThreshold); } } - const ping = watchdogTimer(options.pollInterval, options.hungThreshold, watchdogTimeout); + const ping = watchdogTimer(options.pollInterval, options.anrThreshold, watchdogTimeout); process.on('message', () => { ping(); @@ -172,7 +172,7 @@ export function arnWatchdog(options: Partial): Promise { const anrOptions: Options = { entryScript: options.entryScript || process.argv[1], pollInterval: options.pollInterval || DEFAULT_INTERVAL, - hungThreshold: options.hungThreshold || DEFAULT_HANG_THRESHOLD, + anrThreshold: options.anrThreshold || DEFAULT_HANG_THRESHOLD, captureStackTrace: !!options.captureStackTrace, debug: !!options.debug, }; From a6246de45e4a27a64d5400db6e49ba21fe8bc38f Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 14:16:58 +0100 Subject: [PATCH 05/12] fix integration test --- packages/node-integration-tests/suites/anr/scenario.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/node-integration-tests/suites/anr/scenario.js b/packages/node-integration-tests/suites/anr/scenario.js index a13fc7f95b67..75f006bf5390 100644 --- a/packages/node-integration-tests/suites/anr/scenario.js +++ b/packages/node-integration-tests/suites/anr/scenario.js @@ -16,7 +16,7 @@ Sentry.init({ }, }); -Sentry.arnWatchdog({ captureStackTrace: true, hungThreshold: 200, debug: true }).then(() => { +Sentry.arnWatchdog({ captureStackTrace: true, anrThreshold: 200, debug: true }).then(() => { function longWork() { for (let i = 0; i < 100; i++) { const salt = crypto.randomBytes(128).toString('base64'); From 15a2b4a4f6a9dcec2802343ba17f21e93719cd10 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 14:55:17 +0100 Subject: [PATCH 06/12] Rename function --- .../suites/anr/scenario.js | 2 +- packages/node/src/anr/index.ts | 21 +++++++++++++++---- packages/node/src/index.ts | 2 +- 3 files changed, 19 insertions(+), 6 deletions(-) diff --git a/packages/node-integration-tests/suites/anr/scenario.js b/packages/node-integration-tests/suites/anr/scenario.js index 75f006bf5390..00e4f95d816c 100644 --- a/packages/node-integration-tests/suites/anr/scenario.js +++ b/packages/node-integration-tests/suites/anr/scenario.js @@ -16,7 +16,7 @@ Sentry.init({ }, }); -Sentry.arnWatchdog({ captureStackTrace: true, anrThreshold: 200, debug: true }).then(() => { +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'); diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index affdfef85668..bbf83047c1d5 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -159,14 +159,27 @@ function handleChildProcess(options: Options): void { } /** - * Create a watchdog process to report Application Not Responding (ANR) errors. + * Starts a child process that detects Application Not Responding (ANR) errors. * - * It's important to await on the returned promise before your app code to ensure this code does not run in the watchdog - * process. + * It's important to await on the returned promise before your app code to ensure this code does not run in the ANR + * child process. * + * ```js + * import { init, enableANRDetection } from '@sentry/node'; * + * init({ dsn: "__DSN__" }); + * + * // with ESM + * await enableANRDetection({ captureStackTrace: true }); + * runApp(); + * + * // with CJS + * enableANRDetection({ captureStackTrace: true }).then(() => { + * runApp(); + * }); + * ``` */ -export function arnWatchdog(options: Partial): Promise { +export function enableANRDetection(options: Partial): Promise { const isChildProcess = !!process.send; const anrOptions: Options = { diff --git a/packages/node/src/index.ts b/packages/node/src/index.ts index 7e12661cfc76..392c68806099 100644 --- a/packages/node/src/index.ts +++ b/packages/node/src/index.ts @@ -71,7 +71,7 @@ export { defaultIntegrations, init, defaultStackParser, getSentryRelease } from export { addRequestDataToEvent, DEFAULT_USER_INCLUDES, extractRequestData } from './requestdata'; export { deepReadDirSync } from './utils'; export { getModuleFromFilename } from './module'; -export { arnWatchdog } from './anr'; +export { enableANRDetection } from './anr'; import { Integrations as CoreIntegrations } from '@sentry/core'; From 852e7ceec3a51a3aa7a305182459dd1f23471323 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 18:34:56 +0100 Subject: [PATCH 07/12] Don't capitalise the acronym --- packages/node-integration-tests/suites/anr/scenario.js | 2 +- packages/node/src/anr/index.ts | 8 ++++---- packages/node/src/index.ts | 2 +- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/node-integration-tests/suites/anr/scenario.js b/packages/node-integration-tests/suites/anr/scenario.js index 00e4f95d816c..3abadc09b9c3 100644 --- a/packages/node-integration-tests/suites/anr/scenario.js +++ b/packages/node-integration-tests/suites/anr/scenario.js @@ -16,7 +16,7 @@ Sentry.init({ }, }); -Sentry.enableANRDetection({ captureStackTrace: true, anrThreshold: 200, debug: true }).then(() => { +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'); diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index bbf83047c1d5..e8c6ee61b84e 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -165,21 +165,21 @@ function handleChildProcess(options: Options): void { * child process. * * ```js - * import { init, enableANRDetection } from '@sentry/node'; + * import { init, enableAnrDetection } from '@sentry/node'; * * init({ dsn: "__DSN__" }); * * // with ESM - * await enableANRDetection({ captureStackTrace: true }); + * await enableAnrDetection({ captureStackTrace: true }); * runApp(); * * // with CJS - * enableANRDetection({ captureStackTrace: true }).then(() => { + * enableAnrDetection({ captureStackTrace: true }).then(() => { * runApp(); * }); * ``` */ -export function enableANRDetection(options: Partial): Promise { +export function enableAnrDetection(options: Partial): Promise { const isChildProcess = !!process.send; const anrOptions: Options = { diff --git a/packages/node/src/index.ts b/packages/node/src/index.ts index 392c68806099..503f2749ea29 100644 --- a/packages/node/src/index.ts +++ b/packages/node/src/index.ts @@ -71,7 +71,7 @@ export { defaultIntegrations, init, defaultStackParser, getSentryRelease } from export { addRequestDataToEvent, DEFAULT_USER_INCLUDES, extractRequestData } from './requestdata'; export { deepReadDirSync } from './utils'; export { getModuleFromFilename } from './module'; -export { enableANRDetection } from './anr'; +export { enableAnrDetection } from './anr'; import { Integrations as CoreIntegrations } from '@sentry/core'; From 549beda8c41eea9a14f19ea0354820aab725be29 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 19:17:01 +0100 Subject: [PATCH 08/12] Also test ESM --- .../suites/anr/scenario.mjs | 31 +++++++++++ .../node-integration-tests/suites/anr/test.ts | 55 ++++++++++++++----- 2 files changed, 72 insertions(+), 14 deletions(-) create mode 100644 packages/node-integration-tests/suites/anr/scenario.mjs diff --git a/packages/node-integration-tests/suites/anr/scenario.mjs b/packages/node-integration-tests/suites/anr/scenario.mjs new file mode 100644 index 000000000000..ba9c8623da7e --- /dev/null +++ b/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://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); diff --git a/packages/node-integration-tests/suites/anr/test.ts b/packages/node-integration-tests/suites/anr/test.ts index d43330b8567b..63a408f18786 100644 --- a/packages/node-integration-tests/suites/anr/test.ts +++ b/packages/node-integration-tests/suites/anr/test.ts @@ -5,27 +5,54 @@ import * as path from 'path'; const NODE_VERSION = parseSemver(process.versions.node).major || 0; -test('should report ANR when event loop blocked', done => { - // The stack trace is different when node < 12 - const testFramesDetails = NODE_VERSION >= 12; +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); + expect.assertions(testFramesDetails ? 6 : 4); - const testScriptPath = path.resolve(__dirname, 'scenario.js'); + const testScriptPath = path.resolve(__dirname, 'scenario.js'); - childProcess.exec(`node ${testScriptPath}`, { encoding: 'utf8' }, (_, stdout) => { - const event = JSON.parse(stdout) as Event; + 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].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) { + 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 => { + // The stack trace is different when node < 12 + if (NODE_VERSION < 12) { + 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(); + done(); + }); }); }); From 4aa73be73c1a15c33ae22e6f22381630c5559f86 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 20:07:35 +0100 Subject: [PATCH 09/12] Dont test ESM on node v12 --- packages/node-integration-tests/suites/anr/test.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/packages/node-integration-tests/suites/anr/test.ts b/packages/node-integration-tests/suites/anr/test.ts index 63a408f18786..ec820dca9c62 100644 --- a/packages/node-integration-tests/suites/anr/test.ts +++ b/packages/node-integration-tests/suites/anr/test.ts @@ -32,8 +32,7 @@ describe('should report ANR when event loop blocked', () => { }); test('ESM', done => { - // The stack trace is different when node < 12 - if (NODE_VERSION < 12) { + if (NODE_VERSION < 14) { done(); return; } From 3cd6b8547a608af388e6ec0b65a4785dfa85830c Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Thu, 21 Sep 2023 21:06:44 +0100 Subject: [PATCH 10/12] Move watchdog timer to utils --- packages/node/src/anr/index.ts | 24 +----------------------- packages/utils/src/anr.ts | 29 +++++++++++++++++++++++++++++ packages/utils/src/index.ts | 1 + 3 files changed, 31 insertions(+), 23 deletions(-) create mode 100644 packages/utils/src/anr.ts diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index e8c6ee61b84e..c0f2749915ff 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -1,4 +1,5 @@ import type { Event, StackFrame } from '@sentry/types'; +import { watchdogTimer } from '@sentry/utils'; import { fork } from 'child_process'; import * as inspector from 'inspector'; @@ -41,29 +42,6 @@ interface Options { debug: boolean; } -function watchdogTimer(pollInterval: number, anrThreshold: number, callback: () => void): () => void { - let lastPoll = process.hrtime(); - let triggered = false; - - setInterval(() => { - const [seconds, nanoSeconds] = process.hrtime(lastPoll); - const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); - - if (triggered === false && diffMs > pollInterval + anrThreshold) { - triggered = true; - callback(); - } - - if (diffMs < pollInterval + anrThreshold) { - triggered = false; - } - }, 10); - - return () => { - lastPoll = process.hrtime(); - }; -} - function sendEvent(blockedMs: number, frames?: StackFrame[]): void { const event: Event = { level: 'error', diff --git a/packages/utils/src/anr.ts b/packages/utils/src/anr.ts new file mode 100644 index 000000000000..bcfd12219cc3 --- /dev/null +++ b/packages/utils/src/anr.ts @@ -0,0 +1,29 @@ +/** + * A node.js watchdog timer + * @param pollInterval The interval that we expect to get polled at + * @param anrThreshold The threshold for when we consider ANR + * @param callback The callback to call for ANR + * @returns + */ +export function watchdogTimer(pollInterval: number, anrThreshold: number, callback: () => void): () => void { + let lastPoll = process.hrtime(); + let triggered = false; + + setInterval(() => { + const [seconds, nanoSeconds] = process.hrtime(lastPoll); + const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); + + if (triggered === false && diffMs > pollInterval + anrThreshold) { + triggered = true; + callback(); + } + + if (diffMs < pollInterval + anrThreshold) { + triggered = false; + } + }, 20); + + return () => { + lastPoll = process.hrtime(); + }; +} diff --git a/packages/utils/src/index.ts b/packages/utils/src/index.ts index 8de4941f6b96..81f4d947cd0d 100644 --- a/packages/utils/src/index.ts +++ b/packages/utils/src/index.ts @@ -31,3 +31,4 @@ export * from './url'; export * from './userIntegrations'; export * from './cache'; export * from './eventbuilder'; +export * from './anr'; From e01e2ff812408768a0fd41a832198fbe65ba0bec Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Fri, 22 Sep 2023 16:21:36 +0100 Subject: [PATCH 11/12] Apply suggestions from code review Co-authored-by: Abhijeet Prasad --- packages/node/src/anr/index.ts | 2 +- packages/utils/src/anr.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index c0f2749915ff..95f87f18d14d 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -17,7 +17,7 @@ interface Options { */ entryScript: string; /** - * Interval to send alive messages to the child process. + * Interval to send heartbeat messages to the child process. * * Defaults to 50ms. */ diff --git a/packages/utils/src/anr.ts b/packages/utils/src/anr.ts index bcfd12219cc3..a2a9ebff7a9d 100644 --- a/packages/utils/src/anr.ts +++ b/packages/utils/src/anr.ts @@ -13,7 +13,7 @@ export function watchdogTimer(pollInterval: number, anrThreshold: number, callba const [seconds, nanoSeconds] = process.hrtime(lastPoll); const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); - if (triggered === false && diffMs > pollInterval + anrThreshold) { + if (!triggered && diffMs > pollInterval + anrThreshold) { triggered = true; callback(); } From 51cc01c15a640aded7a571a8afa8ea8bc42b2586 Mon Sep 17 00:00:00 2001 From: Tim Fish Date: Mon, 25 Sep 2023 15:37:44 +0100 Subject: [PATCH 12/12] Add more debug output, more robust error handling, watchdogTimer back to node sdk --- packages/node/src/anr/index.ts | 125 +++++++++++++++++++++++++-------- packages/utils/src/anr.ts | 29 -------- packages/utils/src/index.ts | 1 - 3 files changed, 94 insertions(+), 61 deletions(-) delete mode 100644 packages/utils/src/anr.ts diff --git a/packages/node/src/anr/index.ts b/packages/node/src/anr/index.ts index c0f2749915ff..934d5959f9c7 100644 --- a/packages/node/src/anr/index.ts +++ b/packages/node/src/anr/index.ts @@ -1,5 +1,5 @@ import type { Event, StackFrame } from '@sentry/types'; -import { watchdogTimer } from '@sentry/utils'; +import { logger } from '@sentry/utils'; import { fork } from 'child_process'; import * as inspector from 'inspector'; @@ -9,6 +9,36 @@ import { captureStackTrace } from './debugger'; const DEFAULT_INTERVAL = 50; const DEFAULT_HANG_THRESHOLD = 5000; +/** + * A node.js watchdog timer + * @param pollInterval The interval that we expect to get polled at + * @param anrThreshold The threshold for when we consider ANR + * @param callback The callback to call for ANR + * @returns A function to call to reset the timer + */ +function watchdogTimer(pollInterval: number, anrThreshold: number, callback: () => void): () => void { + let lastPoll = process.hrtime(); + let triggered = false; + + setInterval(() => { + const [seconds, nanoSeconds] = process.hrtime(lastPoll); + const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); + + if (triggered === false && diffMs > pollInterval + anrThreshold) { + triggered = true; + callback(); + } + + if (diffMs < pollInterval + anrThreshold) { + triggered = false; + } + }, 20); + + return () => { + lastPoll = process.hrtime(); + }; +} + interface Options { /** * The app entry script. This is used to run the same script as the child process. @@ -69,44 +99,69 @@ function sendEvent(blockedMs: number, frames?: StackFrame[]): void { } function startChildProcess(options: Options): void { - const env = { ...process.env }; - - if (options.captureStackTrace) { - inspector.open(); - env.SENTRY_INSPECT_URL = inspector.url(); + function log(message: string, err?: unknown): void { + if (options.debug) { + if (err) { + logger.log(`[ANR] ${message}`, err); + } else { + logger.log(`[ANR] ${message}`); + } + } } - const child = fork(options.entryScript, { - env, - stdio: options.debug ? 'inherit' : 'ignore', - }); - // The child process should not keep the main process alive - child.unref(); - - const timer = setInterval(() => { - try { - // message the child process to tell it the main event loop is still running - child.send('ping'); - } catch (_) { - // + try { + const env = { ...process.env }; + + if (options.captureStackTrace) { + inspector.open(); + env.SENTRY_INSPECT_URL = inspector.url(); } - }, options.pollInterval); - child.on('error', () => { - clearTimeout(timer); - }); - child.on('disconnect', () => { - clearTimeout(timer); - }); - child.on('exit', () => { - clearTimeout(timer); - }); + const child = fork(options.entryScript, { + env, + stdio: options.debug ? 'inherit' : 'ignore', + }); + // The child process should not keep the main process alive + child.unref(); + + const timer = setInterval(() => { + try { + // message the child process to tell it the main event loop is still running + child.send('ping'); + } catch (_) { + // + } + }, options.pollInterval); + + const end = (err: unknown): void => { + clearInterval(timer); + log('Child process ended', err); + }; + + child.on('error', end); + child.on('disconnect', end); + child.on('exit', end); + } catch (e) { + log('Failed to start child process', e); + } } function handleChildProcess(options: Options): void { + function log(message: string): void { + if (options.debug) { + logger.log(`[ANR child process] ${message}`); + } + } + + log('Started'); + addGlobalEventProcessor(event => { // Strip sdkProcessingMetadata from all child process events to remove trace info delete event.sdkProcessingMetadata; + event.tags = { + ...event.tags, + 'process.name': 'ANR', + }; return event; }); @@ -114,17 +169,23 @@ function handleChildProcess(options: Options): void { // if attachStackTrace is enabled, we'll have a debugger url to connect to if (process.env.SENTRY_INSPECT_URL) { + log('Connecting to debugger'); + debuggerPause = captureStackTrace(process.env.SENTRY_INSPECT_URL, frames => { + log('Capturing event with stack frames'); sendEvent(options.anrThreshold, frames); }); } async function watchdogTimeout(): Promise { + log('Watchdog timeout'); const pauseAndCapture = await debuggerPause; if (pauseAndCapture) { + log('Pausing debugger to capture stack trace'); pauseAndCapture(); } else { + log('Capturing event'); sendEvent(options.anrThreshold); } } @@ -137,6 +198,8 @@ function handleChildProcess(options: Options): void { } /** + * **Note** This feature is still in beta so there may be breaking changes in future releases. + * * Starts a child process that detects Application Not Responding (ANR) errors. * * It's important to await on the returned promise before your app code to ensure this code does not run in the ANR @@ -147,11 +210,11 @@ function handleChildProcess(options: Options): void { * * init({ dsn: "__DSN__" }); * - * // with ESM + * // with ESM + Node 14+ * await enableAnrDetection({ captureStackTrace: true }); * runApp(); * - * // with CJS + * // with CJS or Node 10+ * enableAnrDetection({ captureStackTrace: true }).then(() => { * runApp(); * }); diff --git a/packages/utils/src/anr.ts b/packages/utils/src/anr.ts deleted file mode 100644 index bcfd12219cc3..000000000000 --- a/packages/utils/src/anr.ts +++ /dev/null @@ -1,29 +0,0 @@ -/** - * A node.js watchdog timer - * @param pollInterval The interval that we expect to get polled at - * @param anrThreshold The threshold for when we consider ANR - * @param callback The callback to call for ANR - * @returns - */ -export function watchdogTimer(pollInterval: number, anrThreshold: number, callback: () => void): () => void { - let lastPoll = process.hrtime(); - let triggered = false; - - setInterval(() => { - const [seconds, nanoSeconds] = process.hrtime(lastPoll); - const diffMs = Math.floor(seconds * 1e3 + nanoSeconds / 1e6); - - if (triggered === false && diffMs > pollInterval + anrThreshold) { - triggered = true; - callback(); - } - - if (diffMs < pollInterval + anrThreshold) { - triggered = false; - } - }, 20); - - return () => { - lastPoll = process.hrtime(); - }; -} diff --git a/packages/utils/src/index.ts b/packages/utils/src/index.ts index 81f4d947cd0d..8de4941f6b96 100644 --- a/packages/utils/src/index.ts +++ b/packages/utils/src/index.ts @@ -31,4 +31,3 @@ export * from './url'; export * from './userIntegrations'; export * from './cache'; export * from './eventbuilder'; -export * from './anr';