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 <joyeec9h3@gmail.com>

Author: joyeecheung

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