debugger,test: deflake resume failure test and add debug logs

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 =

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)) {

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,
 });