From e9cb3fcbf9cc32953cfe839623262b302d7a24f7 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Sat, 23 May 2026 21:29:00 +0200 Subject: [PATCH] debugger,test: deflake resume failure test and add debug logs 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. Accept both probe failure and timeout as valid to accommodate this flakiness. This patch also adds more debug logs to the probe mode to show more information in case it flakes again in the CI Signed-off-by: Joyee Cheung --- lib/internal/debugger/inspect_probe.js | 20 ++++++++++- test/common/debugger-probe.js | 2 +- .../test-debugger-probe-failure-resume.js | 35 +++++++++++++++---- 3 files changed, 49 insertions(+), 8 deletions(-) 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, });