test: fix test-watch-mode-inspect
This PR fixes flakiness in watch mode tests in test/sequential/test-watch-mode-inspect.mjs. The changes made introduce a basic synchronization between restarting the process (rewriting the file) and its execution. Previously, it was possible to restart the process while it was still executing (while getting debugged PID) which caused the test to fail, and in some cases even leave it hanging.
With these changes, one problem still persists. Rarely, in less than 1% of runs, logs from the start of the process, until the first restart are missing. Eg. instead of getting (inspector helper debug logs included)
[test] Connecting to a child Node process
[test] Testing /json/list
[err] (node:5976) ExperimentalWarning: Watch mode is an experimental feature and might change at any time
[err] (Use `node --trace-warnings ...` to show where the warning was created)
[err]
[err] Debugger listening on ws://127.0.0.1:50525/d2193ebf-2311-4fee-9ae9-f9e0c0e53d79
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[out] safe to debug now
[out]
[sent] {"method":"Runtime.enable","id":1}
[err] Debugger attached.
[err]
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\powershell.exe[6560]","uniqueId":"-3771975452535908737.-4278556484855783730","auxData":{"isDefault":true}}}}
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":2,"origin":"","name":"internal","uniqueId":"-3948129943118009310.-4596286994008522080","auxData":{"isDefault":false}}}}
[received] {"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"safe to debug now"}],"executionContextId":1,"timestamp":1669136444561.225,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"484","url":"file:///C:/_work/node/test/fixtures/watch-mode/inspect.js","lineNumber":0,"columnNumber":8}]}}}
[received] {"id":1,"result":{}}
[sent] {"method":"Runtime.evaluate","params":{"expression":"process.pid"},"id":2}
[received] {"id":2,"result":{"result":{"type":"number","value":6560,"description":"6560"}}}
[test] Connecting to a child Node process
[test] Testing /json/list
[out] Restarting 'C:\\_work\\node\\test\\fixtures\\watch-mode\\inspect.js'
[out]
[err] Debugger listening on ws://127.0.0.1:50528/879bc134-e4a4-42ae-9a8e-23ddc6077efb
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[out] safe to debug now
[out]
[sent] {"method":"Runtime.enable","id":1}
[err] Debugger attached.
[err]
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\powershell.exe[3460]","uniqueId":"-974935170866930654.-2963546899149149482","auxData":{"isDefault":true}}}}
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":2,"origin":"","name":"internal","uniqueId":"-9144310994928849777.-239544464264725541","auxData":{"isDefault":false}}}}
[received] {"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"safe to debug now"}],"executionContextId":1,"timestamp":1669136444639.24,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"484","url":"file:///C:/_work/node/test/fixtures/watch-mode/inspect.js","lineNumber":0,"columnNumber":8}]}}}
[received] {"id":1,"result":{}}
[sent] {"method":"Runtime.evaluate","params":{"expression":"process.pid"},"id":2}
[received] {"id":2,"result":{"result":{"type":"number","value":3460,"description":"3460"}}}
[err] Debugger ending on ws://127.0.0.1:50528/879bc134-e4a4-42ae-9a8e-23ddc6077efb
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err] test gets
[test] Connecting to a child Node process
[test] Testing /json/list
[err] (node:6480) ExperimentalWarning: Watch mode is an experimental feature and might change at any time
[err] (Use `node --trace-warnings ...` to show where the warning was created)
[err]
[err] Debugger listening on ws://127.0.0.1:50519/2e587f29-d2d9-4852-884b-acf770143b60
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[sent] {"method":"Runtime.enable","id":1}
[err] Debugger attached.
[err]
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\powershell.exe[6544]","uniqueId":"-2869413537932388801.-1202960629722598587","auxData":{"isDefault":true}}}}
[received] {"id":1,"result":{}}
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":2,"origin":"","name":"internal","uniqueId":"6241213445752131585.-1035681654837502813","auxData":{"isDefault":false}}}}
[received] {"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"safe to debug now"}],"executionContextId":1,"timestamp":1669136443758.198,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"484","url":"file:///C:/_work/node/test/fixtures/watch-mode/inspect.js","lineNumber":0,"columnNumber":8},{"functionName":"Module._compile","scriptId":"458","url":"node:internal/modules/cjs/loader","lineNumber":1212,"columnNumber":13},{"functionName":"Module._extensions..js","scriptId":"458","url":"node:internal/modules/cjs/loader","lineNumber":1266,"columnNumber":9},{"functionName":"Module.load","scriptId":"458","url":"node:internal/modules/cjs/loader","lineNumber":1075,"columnNumber":31},{"functionName":"Module._load","scriptId":"458","url":"node:internal/modules/cjs/loader","lineNumber":916,"columnNumber":11},{"functionName":"executeUserEntryPoint","scriptId":"482","url":"node:internal/modules/run_main","lineNumber":81,"columnNumber":11},{"functionName":"","scriptId":"439","url":"node:internal/main/run_main_module","lineNumber":22,"columnNumber":46}]}}}
[sent] {"method":"Runtime.evaluate","params":{"expression":"process.pid"},"id":2}
[received] {"id":2,"result":{"result":{"type":"number","value":6544,"description":"6544"}}}
[test] Connecting to a child Node process
[test] Testing /json/list
[err] Debugger ending on ws://127.0.0.1:50519/2e587f29-d2d9-4852-884b-acf770143b60
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[out] Restarting 'C:\\_work\\node\\test\\fixtures\\watch-mode\\inspect.js'
[out]
[err] Debugger listening on ws://127.0.0.1:50522/c372262b-4eb2-44d8-a421-acffd65b6c51
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err]
[out] safe to debug now
[out]
[sent] {"method":"Runtime.enable","id":1}
[err] Debugger attached.
[err]
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"C:\\Windows\\System32\\WindowsPowerShell\\v1.0\\powershell.exe[4128]","uniqueId":"4239842680887786250.1198529520719410266","auxData":{"isDefault":true}}}}
[received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":2,"origin":"","name":"internal","uniqueId":"-2115048448301876270.-3406283542544322629","auxData":{"isDefault":false}}}}
[received] {"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"safe to debug now"}],"executionContextId":1,"timestamp":1669136443854.872,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"484","url":"file:///C:/_work/node/test/fixtures/watch-mode/inspect.js","lineNumber":0,"columnNumber":8}]}}}
[received] {"id":1,"result":{}}
[sent] {"method":"Runtime.evaluate","params":{"expression":"process.pid"},"id":2}
[received] {"id":2,"result":{"result":{"type":"number","value":4128,"description":"4128"}}}
[err] Debugger ending on ws://127.0.0.1:50522/c372262b-4eb2-44d8-a421-acffd65b6c51
[err]
[err] For help, see: https://nodejs.org/en/docs/inspector
[err] It is worth noting that although safe to debug now is sometimes not caught via NodeInstance.on('stdout', (data) => { stdout.push(data); }); it is always caught via InspectorSession.waitForConsoleOutput('log', 'safe to debug now');
This behavior seems to be random, and by the looks of it, it's related to watch mode in a more general way, not directly related to these tests. It should probably be addressed in a separate issue and PR.