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>
PR-URL: #63524Fixes: #63505
Reviewed-By: Gürgün Dayıoğlu <hey@gurgun.day>
Reviewed-By: Chemi Atlow <chemi@atlow.co.il>
Reviewed-By: Chengzhong Wu <legendecas@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');
+constdebug=require('internal/util/debuglog').debuglog('inspect_probe');
 
 constInspectClient=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 {
 asynccallCdp(method,params,probe=null){
 if(this.finished){throwkInspectorFailedSentinel;}
 this.inFlight={__proto__: null, method, probe };
+debug('CDP -> %s%s',method,probe!==null ? `, probe=${probe.index}` : '');
 try{
 constresult=awaitthis.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){throwkInspectorFailedSentinel;}
+if(this.finished){
+debug('CDP <- %s discarded (already finished)',method);
+throwkInspectorFailedSentinel;
+}
+debug('CDP <- %s (success)',method);
 returnresult;
 }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);
 constchild=this.child;
 constexitedAbnormally=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){
 consthasProbeAttribution=

test/common/debugger-probe.js

@@ -52,7 +52,7 @@ function normalizeProbeReport(value) {
 }
 
 functionassertProbeJson(output,expected){
-constnormalized=JSON.parse(output);
+constnormalized=typeofoutput==='string' ? JSON.parse(output) : output;
 constlastResult=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';
 
 constcommon=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,{
+constexpected={
 v: 2,
  probes,
 results: [{
@@ -34,7 +36,14 @@ spawnSyncAndExit(process.execPath, [
 hit: 1,
  location,
 result: {type: 'number',value: 1,description: '1'},
-},{
+}]
+};
+
+constactual=JSON.parse(output);
+
+constcode=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},
 },
 },
-}],
-});
+});
+}elseif(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,
 });