diff --git a/lib/internal/debugger/inspect_probe.js b/lib/internal/debugger/inspect_probe.js index 14f7413fea8ef1..fc9f3056f52341 100644 --- a/lib/internal/debugger/inspect_probe.js +++ b/lib/internal/debugger/inspect_probe.js @@ -25,6 +25,7 @@ const { const { clearTimeout, setTimeout } = require('timers'); const { SideEffectFreeRegExpPrototypeSymbolReplace } = require('internal/util'); +const debug = require('internal/util/debuglog').debuglog('inspect_probe'); const InspectClient = require('internal/debugger/inspect_client'); const { @@ -477,6 +478,7 @@ class ProbeInspectorSession { finish(exitCode, terminal) { if (this.finished) { return; } + debug('finish: exitCode=%d, terminal=%s', exitCode, terminal?.event); this.finished = true; if (this.timeout !== null) { clearTimeout(this.timeout); @@ -523,6 +525,8 @@ class ProbeInspectorSession { } onChildExit(code, signal) { + debug('child exit: code=%s signal=%s connected=%s started=%s finished=%s inFlight=%j', + code, signal, this.connected, this.started, this.finished, this.inFlight); // Pre-connect exits are deliberately silent: the target never reached // a state where probes could be set, so any report would be empty. if (!this.connected) { return; } @@ -543,6 +547,8 @@ class ProbeInspectorSession { } onClientClose() { + debug('client close: disconnectRequested=%s finished=%s inFlight=%j', + this.disconnectRequested, this.finished, this.inFlight); if (!this.connected) { return; } if (this.disconnectRequested) { return; } if (this.finished) { return; } @@ -664,13 +670,21 @@ class ProbeInspectorSession { async callCdp(method, params, probe = null) { if (this.finished) { throw kInspectorFailedSentinel; } this.inFlight = { __proto__: null, method, probe }; + debug('CDP -> %s%s', method, probe !== null ? `, probe=${probe.index}` : ''); try { const result = await this.client.callMethod(method, params); // A timeout or process exit can finish the report while the CDP request // is still outstanding. Ignore the late reply in that case. - if (this.finished) { throw kInspectorFailedSentinel; } + if (this.finished) { + debug('CDP <- %s discarded (already finished)', method); + throw kInspectorFailedSentinel; + } + debug('CDP <- %s (success)', method); return result; } catch (err) { + if (err !== kInspectorFailedSentinel) { // Already handled. + debug('CDP <- %s error: %s', method, err?.code); + } if (this.disconnectRequested) { // Only the in-flight evaluation gets attribution. Other rejections // under disconnect are downstream noise. @@ -718,6 +732,8 @@ class ProbeInspectorSession { // Records the first inspector-side terminal for the session, later callers are ignored. recordInspectorFailure({ reason, advice, cdpError, internalError }) { if (this.finished) { return; } + debug('recordInspectorFailure "%s": inFlight=%j, lastProbeIndex=%s, cdpError=%j', + reason, this.inFlight, this.lastProbeIndex, cdpError); const child = this.child; const exitedAbnormally = child !== null && (child.signalCode !== null || (child.exitCode !== null && child.exitCode !== 0)); @@ -785,6 +801,8 @@ class ProbeInspectorSession { startTimeout() { this.timeout = setTimeout(() => { + debug('timeout fired: finished=%s, inFlight=%j, lastProbeIndex=%s', + this.finished, this.inFlight, this.lastProbeIndex); if (this.finished) { return; } if (this.inFlight !== null) { const hasProbeAttribution = diff --git a/test/common/debugger-probe.js b/test/common/debugger-probe.js index bc5c206bb78926..c2ed825a26064b 100644 --- a/test/common/debugger-probe.js +++ b/test/common/debugger-probe.js @@ -52,7 +52,7 @@ function normalizeProbeReport(value) { } function assertProbeJson(output, expected) { - const normalized = JSON.parse(output); + const normalized = typeof output === 'string' ? JSON.parse(output) : output; const lastResult = normalized.results?.[normalized.results.length - 1]; if (isProbeSegvTeardown(lastResult)) { diff --git a/test/parallel/test-debugger-probe-failure-resume.js b/test/parallel/test-debugger-probe-failure-resume.js index e5578ec452e1e7..8305ea9c8004b5 100644 --- a/test/parallel/test-debugger-probe-failure-resume.js +++ b/test/parallel/test-debugger-probe-failure-resume.js @@ -1,5 +1,7 @@ // This tests that a probe expression resuming the target through its own -// inspector.Session surfaces as probe_failure. +// inspector.Session is surfaced as a probe-side failure. The terminal event +// can be either probe_failure or probe_timeout depending on a race in V8's +// nested pause-loop drain. 'use strict'; const common = require('../common'); @@ -21,11 +23,11 @@ spawnSyncAndExit(process.execPath, [ 'inspect', '--json', '--probe', `${fixture}:12`, '--expr', probes[0].expr, fixture, -], { cwd }, { +], { cwd, env: { ...process.env, NODE_DEBUG: 'inspect_probe' } }, { status: 1, signal: null, stdout(output) { - assertProbeJson(output, { + const expected = { v: 2, probes, results: [{ @@ -34,7 +36,14 @@ spawnSyncAndExit(process.execPath, [ hit: 1, location, result: { type: 'number', value: 1, description: '1' }, - }, { + }] + }; + + const actual = JSON.parse(output); + + const code = actual.results.at(-1)?.error?.code; + if (code === 'probe_failure') { + expected.results.push({ event: 'error', pending: [], error: { @@ -50,8 +59,22 @@ spawnSyncAndExit(process.execPath, [ protocolError: { message: 'Can only perform operation while paused.', code: -32000 }, }, }, - }], - }); + }); + } else if (code === 'probe_timeout') { + // On slow CI, the outer Debugger.resume can be picked up in the same drain pass as + // the Debugger.evaluateOnCallFrame, while V8 still considers the context paused. + // In this case both resume calls may succeed and the process can continue running from + // the setInterval until the timeout. + expected.results.push({ + event: 'timeout', + pending: [], + error: { + code: 'probe_timeout', + message: 'Timed out after 30000ms waiting for target completion' + }, + }); + } + assertProbeJson(actual, expected); }, trim: true, });