diff --git a/src/main/integrations/renderer-anr.ts b/src/main/integrations/renderer-anr.ts index 23a9df8d..63e20e46 100644 --- a/src/main/integrations/renderer-anr.ts +++ b/src/main/integrations/renderer-anr.ts @@ -1,6 +1,6 @@ import type { Client, Event, Integration, StackFrame } from '@sentry/core'; import { captureEvent, debug, defineIntegration, stripSentryFramesAndReverse } from '@sentry/core'; -import { callFrameToStackFrame, watchdogTimer } from '@sentry/core/server'; +import { callFrameToStackFrame } from '@sentry/core/server'; import { createGetModuleFromFilename } from '@sentry/node'; import type { WebContents } from 'electron'; import { app, powerMonitor } from 'electron'; @@ -9,11 +9,18 @@ import { addHeaderToSession } from '../header-injection.js'; import type { ElectronMainOptionsInternal } from '../sdk.js'; import { sessionAnr } from '../sessions.js'; import { captureRendererStackFrames } from '../stack-parse.js'; +import type { Watchdog } from '../watchdog.js'; +import { createWatchdog } from '../watchdog.js'; function log(message: string, ...args: unknown[]): void { debug.log(`[Renderer Event Loop Block] ${message}`, ...args); } +// Upper bound for the scriptId -> url map of one renderer. Each eval +// parses a new script, so without a bound the map grows for the life +// of the renderer. +const MAX_TRACKED_SCRIPTS = 10_000; + interface ScriptParsedEventDataType { scriptId: string; url: string; @@ -62,13 +69,25 @@ function debuggerStackTraceCapture(contents: WebContents, pausedStack: StackFram log('Connecting to debugger'); contents.debugger.attach('1.3'); - // Collect scriptId -> url map so we can look up the filenames later + // Collect scriptId -> url map so we can look up the filenames later. + // Paused call frames do not carry a url in Electron. const scripts = new Map(); const getModuleFromFilename = createGetModuleFromFilename(app.getAppPath()); + // A new document parses its own scripts, so the old ones are gone + contents.on('did-navigate', () => scripts.clear()); + contents.debugger.on('message', (_, method, params) => { if (method === 'Debugger.scriptParsed') { const param = params as ScriptParsedEventDataType; + + if (scripts.size >= MAX_TRACKED_SCRIPTS) { + const oldest = scripts.keys().next(); + if (!oldest.done) { + scripts.delete(oldest.value); + } + } + scripts.set(param.scriptId, param.url); } else if (method === 'Debugger.paused') { const param = params as PausedEventDataType; @@ -105,7 +124,9 @@ function debuggerStackTraceCapture(contents: WebContents, pausedStack: StackFram } log('Pausing debugger to capture stack trace'); - return contents.debugger.sendCommand('Debugger.pause'); + contents.debugger.sendCommand('Debugger.pause').catch(() => { + // ignore + }); }; } @@ -148,7 +169,7 @@ type RendererEventLoopBlockIntegration = Integration & { */ export const rendererEventLoopBlockIntegration: (options?: Options) => RendererEventLoopBlockIntegration = defineIntegration((options: Options = {}) => { - const rendererWatchdogTimers = new Map>(); + const rendererWatchdogTimers = new Map(); let clientOptions: ElectronMainOptionsInternal | undefined; function getRendererName(contents: WebContents): string | undefined { @@ -183,6 +204,67 @@ export const rendererEventLoopBlockIntegration: (options?: Options) => RendererE captureEvent(event); } + function startWatchdog(contents: WebContents, config: RendererStatus['config']): Watchdog { + let pauseAndCapture: (() => void) | undefined; + + if (config.captureStackTrace) { + const stackCaptureImpl = options.captureNativeStacktrace ? nativeStackTraceCapture : debuggerStackTraceCapture; + + pauseAndCapture = stackCaptureImpl(contents, (frames) => { + log('Event captured with stack frames'); + sendRendererEventLoopBlockEvent(contents, config.anrThreshold, frames); + }); + } + + const watchdog = createWatchdog(createHrTimer, 100, config.anrThreshold, () => { + log('Watchdog timeout'); + if (pauseAndCapture) { + pauseAndCapture(); + } else { + log('Capturing event'); + sendRendererEventLoopBlockEvent(contents, config.anrThreshold); + } + }); + + const disable = (): void => watchdog.enabled(false); + const enable = (): void => watchdog.enabled(true); + const suspend = (): void => watchdog.suspend(); + + // A destroyed webContents never polls again, so the watchdog must + // stop too or it reports a block that never happened + const teardown = (): void => { + watchdog.stop(); + rendererWatchdogTimers.delete(contents); + + if (!contents.isDestroyed()) { + contents.off('blur', disable); + contents.off('focus', enable); + contents.off('render-process-gone', suspend); + } + + powerMonitor.off('suspend', disable); + powerMonitor.off('resume', enable); + powerMonitor.off('lock-screen', disable); + powerMonitor.off('unlock-screen', enable); + }; + + contents.on('blur', disable); + contents.on('focus', enable); + // A crashed renderer stops polling until it is reloaded. The + // watchdog is held rather than disabled, because in protocol mode + // the reloaded page's visibility status can be dropped while its + // new id is still being mapped; its polls then lift the hold. The + // watchdog and the debugger session are kept. + contents.on('render-process-gone', suspend); + contents.once('destroyed', teardown); + powerMonitor.on('suspend', disable); + powerMonitor.on('resume', enable); + powerMonitor.on('lock-screen', disable); + powerMonitor.on('unlock-screen', enable); + + return watchdog; + } + return { name: INTEGRATION_NAME, setup: (client) => { @@ -204,57 +286,9 @@ export const rendererEventLoopBlockIntegration: (options?: Options) => RendererE return (message: RendererStatus, contents: WebContents): void => { let watchdog = rendererWatchdogTimers.get(contents); - // eslint-disable-next-line jsdoc/require-jsdoc - function disable(): void { - watchdog?.enabled(false); - } - - // eslint-disable-next-line jsdoc/require-jsdoc - function enable(): void { - watchdog?.enabled(true); - } - if (watchdog === undefined) { log('Renderer sent first status message', message.config); - let pauseAndCapture: (() => void) | undefined; - - if (message.config.captureStackTrace) { - const stackCaptureImpl = options.captureNativeStacktrace - ? nativeStackTraceCapture - : debuggerStackTraceCapture; - - pauseAndCapture = stackCaptureImpl(contents, (frames) => { - log('Event captured with stack frames'); - sendRendererEventLoopBlockEvent(contents, message.config.anrThreshold, frames); - }); - } - - watchdog = watchdogTimer(createHrTimer, 100, message.config.anrThreshold, async () => { - log('Watchdog timeout'); - if (pauseAndCapture) { - pauseAndCapture(); - } else { - log('Capturing event'); - sendRendererEventLoopBlockEvent(contents, message.config.anrThreshold); - } - }); - - contents.once('destroyed', () => { - rendererWatchdogTimers?.delete(contents); - - powerMonitor.off('suspend', disable); - powerMonitor.off('resume', enable); - powerMonitor.off('lock-screen', disable); - powerMonitor.off('unlock-screen', enable); - }); - - contents.once('blur', disable); - contents.once('focus', enable); - powerMonitor.on('suspend', disable); - powerMonitor.on('resume', enable); - powerMonitor.on('lock-screen', disable); - powerMonitor.on('unlock-screen', enable); - + watchdog = startWatchdog(contents, message.config); rendererWatchdogTimers.set(contents, watchdog); } @@ -262,6 +296,9 @@ export const rendererEventLoopBlockIntegration: (options?: Options) => RendererE if (message.status !== 'alive') { log(`Renderer visibility changed '${message.status}'`); + // A page sends its visibility when it starts, so this message + // comes from a live page and lifts any hold from a crash + watchdog.resume(); watchdog.enabled(message.status === 'visible'); } }; diff --git a/src/main/ipc.ts b/src/main/ipc.ts index e0e20662..76612af2 100644 --- a/src/main/ipc.ts +++ b/src/main/ipc.ts @@ -50,29 +50,57 @@ export const ipcMainHooks = new EventEmitter(); let KNOWN_RENDERERS: Set | undefined; let WINDOW_ID_TO_WEB_CONTENTS: Map | undefined; -function newProtocolRenderer(): void { +/** + * Finds the webContents that sent a protocol `start` request and maps its + * window id to it. + * + * Every page load creates a new window id in the renderer, so a reload + * reaches here with an id that no webContents maps to yet. The lookup + * probes every webContents, including ones already mapped, so the stale + * mapping of a reloaded renderer is replaced. + */ +function newProtocolRenderer(startWindowId: string | undefined): void { KNOWN_RENDERERS = KNOWN_RENDERERS || new Set(); WINDOW_ID_TO_WEB_CONTENTS = WINDOW_ID_TO_WEB_CONTENTS || new Map(); + if (startWindowId && WINDOW_ID_TO_WEB_CONTENTS.has(startWindowId)) { + return; + } + for (const wc of webContents.getAllWebContents()) { const wcId = wc.id; - if (KNOWN_RENDERERS.has(wcId)) { + + if (wc.isDestroyed()) { continue; } - if (!wc.isDestroyed()) { - wc.executeJavaScript('window.__SENTRY_RENDERER_ID__').then((windowId: string | undefined) => { - if (windowId && KNOWN_RENDERERS && WINDOW_ID_TO_WEB_CONTENTS) { - KNOWN_RENDERERS.add(wcId); - WINDOW_ID_TO_WEB_CONTENTS.set(windowId, wcId); + wc.executeJavaScript('window.__SENTRY_RENDERER_ID__').then((windowId: string | undefined) => { + if (!windowId || !KNOWN_RENDERERS || !WINDOW_ID_TO_WEB_CONTENTS) { + return; + } - wc.once('destroyed', () => { - KNOWN_RENDERERS?.delete(wcId); - WINDOW_ID_TO_WEB_CONTENTS?.delete(windowId); - }); + for (const [previousWindowId, previousWcId] of WINDOW_ID_TO_WEB_CONTENTS) { + if (previousWcId === wcId && previousWindowId !== windowId) { + WINDOW_ID_TO_WEB_CONTENTS.delete(previousWindowId); } - }, debug.error); - } + } + + WINDOW_ID_TO_WEB_CONTENTS.set(windowId, wcId); + + if (!KNOWN_RENDERERS.has(wcId)) { + KNOWN_RENDERERS.add(wcId); + + wc.once('destroyed', () => { + KNOWN_RENDERERS?.delete(wcId); + + for (const [mappedWindowId, mappedWcId] of WINDOW_ID_TO_WEB_CONTENTS || []) { + if (mappedWcId === wcId) { + WINDOW_ID_TO_WEB_CONTENTS?.delete(mappedWindowId); + } + } + }); + } + }, debug.error); } } @@ -529,7 +557,7 @@ function configureProtocol(client: Client, ipcUtil: IpcUtils, options: ElectronM const data = request.body; if (ipcUtil.urlMatches(request.url, 'start')) { - newProtocolRenderer(); + newProtocolRenderer(request.windowId); } else if (ipcUtil.urlMatches(request.url, 'scope') && data) { handleScope(options, data.toString()); } else if (ipcUtil.urlMatches(request.url, 'envelope') && data) { diff --git a/src/main/watchdog.ts b/src/main/watchdog.ts new file mode 100644 index 00000000..7dbd5536 --- /dev/null +++ b/src/main/watchdog.ts @@ -0,0 +1,73 @@ +export interface Timer { + getTimeMs: () => number; + reset: () => void; +} + +export interface Watchdog { + /** Marks the watched process as alive */ + poll: () => void; + /** Turns the callback on or off. Polling continues either way. */ + enabled: (state: boolean) => void; + /** + * Holds the callback until `resume()` or until two more polls arrive. + * `enabled` is kept. Two polls, because one message from a crashed + * process can still be in flight when the hold starts. + */ + suspend: () => void; + /** Lifts a hold at once */ + resume: () => void; + /** Stops the watchdog. It cannot be restarted. */ + stop: () => void; +} + +/** + * Calls `callback` once when more than `pollInterval + anrThreshold` ms + * pass without a `poll()`. It arms again once polling resumes. + */ +export function createWatchdog( + createTimer: () => Timer, + pollInterval: number, + anrThreshold: number, + callback: () => void, +): Watchdog { + const timer = createTimer(); + let triggered = false; + let enabled = true; + let pollsUntilResume = 0; + + const interval = setInterval(() => { + const diffMs = timer.getTimeMs(); + + if (!triggered && diffMs > pollInterval + anrThreshold) { + triggered = true; + if (enabled && pollsUntilResume === 0) { + callback(); + } + } + + if (diffMs < pollInterval + anrThreshold) { + triggered = false; + } + }, 20); + + return { + poll: () => { + if (pollsUntilResume > 0) { + pollsUntilResume -= 1; + } + timer.reset(); + }, + enabled: (state: boolean) => { + enabled = state; + }, + suspend: () => { + pollsUntilResume = 2; + }, + resume: () => { + pollsUntilResume = 0; + }, + stop: () => { + clearInterval(interval); + }, + }; +} diff --git a/test/unit/watchdog.test.ts b/test/unit/watchdog.test.ts new file mode 100644 index 00000000..85378f0b --- /dev/null +++ b/test/unit/watchdog.test.ts @@ -0,0 +1,135 @@ +import { afterEach, beforeEach, describe, expect, test, vi } from 'vitest'; +import type { Timer } from '../../src/main/watchdog'; +import { createWatchdog } from '../../src/main/watchdog'; + +const POLL_INTERVAL = 100; +const THRESHOLD = 1000; + +/** A timer driven by the fake clock */ +function createFakeTimer(): Timer { + let last = Date.now(); + + return { + getTimeMs: () => Date.now() - last, + reset: () => { + last = Date.now(); + }, + }; +} + +describe('createWatchdog', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + test('fires once when polling stops', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD); + expect(callback).not.toHaveBeenCalled(); + + vi.advanceTimersByTime(40); + expect(callback).toHaveBeenCalledTimes(1); + + vi.advanceTimersByTime(THRESHOLD * 5); + expect(callback).toHaveBeenCalledTimes(1); + + watchdog.stop(); + }); + + test('does not fire while polled', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + for (let i = 0; i < 50; i++) { + vi.advanceTimersByTime(POLL_INTERVAL); + watchdog.poll(); + } + + expect(callback).not.toHaveBeenCalled(); + watchdog.stop(); + }); + + test('does not fire while disabled and arms again after recovery', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + watchdog.enabled(false); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).not.toHaveBeenCalled(); + + watchdog.enabled(true); + watchdog.poll(); + vi.advanceTimersByTime(40); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).toHaveBeenCalledTimes(1); + + watchdog.stop(); + }); + + test('does not fire while suspended, and one stale poll does not lift the hold', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + watchdog.suspend(); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).not.toHaveBeenCalled(); + + // A message from the crashed process that was still in flight + watchdog.poll(); + vi.advanceTimersByTime(40); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).not.toHaveBeenCalled(); + + watchdog.stop(); + }); + + test('resume lifts the hold at once', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + watchdog.suspend(); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + + watchdog.poll(); + watchdog.resume(); + vi.advanceTimersByTime(40); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).toHaveBeenCalledTimes(1); + + watchdog.stop(); + }); + + test('resumes on the second poll after suspend', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + watchdog.suspend(); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + + watchdog.poll(); + vi.advanceTimersByTime(POLL_INTERVAL); + watchdog.poll(); + vi.advanceTimersByTime(40); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + expect(callback).toHaveBeenCalledTimes(1); + + watchdog.stop(); + }); + + test('never fires after stop', () => { + const callback = vi.fn(); + const watchdog = createWatchdog(createFakeTimer, POLL_INTERVAL, THRESHOLD, callback); + + watchdog.stop(); + vi.advanceTimersByTime(POLL_INTERVAL + THRESHOLD + 40); + + expect(callback).not.toHaveBeenCalled(); + expect(vi.getTimerCount()).toBe(0); + }); +});