test: fix test-watch-mode-inspect

[StefanStojanovic]

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.

Refs: #44898

[StefanStojanovic]

Hi, is there something I can do to help move this forward? I've seen Test ASan failing, but it seems unrelated to my changes.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/48251/

[Trott]

Hi, is there something I can do to help move this forward? I've seen Test ASan failing, but it seems unrelated to my changes.

Test ASan is failing because your branch doesn't have 3b1f389. If you rebase against the main branch and force push, that should fix it. (I tried to rebase and force push to your branch, but I don't have sufficient privileges to do that.)

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/48259/

[StefanStojanovic]

Test ASan is failing because your branch doesn't have 3b1f389. If you rebase against the main branch and force push, that should fix it. (I tried to rebase and force push to your branch, but I don't have sufficient privileges to do that.)

Thanks, @Trott! Rebasing helped with Test ASan, but unfortunately, node-test-commit-osx failed now, could you retrigger CI once again to see if it will pass? The failures look unrelated to my changes.

Also, I have another PR similar to this one (#45585), since it had the same issue as this one and I force-pushed it as well, I guess you'd want to add a request-ci label there too.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/48266/

[nodejs-github-bot]

Commit Queue failed

- Loading data for nodejs/node/pull/45586
✔  Done loading data for nodejs/node/pull/45586
----------------------------------- PR info ------------------------------------
Title      test: fix test-watch-mode-inspect (#45586)
   ⚠  Could not retrieve the email or name of the PR author's from user's GitHub profile!
Branch     StefanStojanovic:mefi-watch-mode-inspect-test -> nodejs:main
Labels     test, needs-ci, watch-mode
Commits    1
 - test: fix test-watch-mode-inspect
Committers 1
 - StefanStojanovic 
PR-URL: https://github.com/nodejs/node/pull/45586
Refs: https://github.com/nodejs/node/issues/44898
Reviewed-By: Moshe Atlow 
Reviewed-By: Erick Wendel 
------------------------------ Generated metadata ------------------------------
PR-URL: https://github.com/nodejs/node/pull/45586
Refs: https://github.com/nodejs/node/issues/44898
Reviewed-By: Moshe Atlow 
Reviewed-By: Erick Wendel 
--------------------------------------------------------------------------------
   ⚠  Commits were pushed since the last review:
   ⚠  - test: fix test-watch-mode-inspect
   ℹ  This PR was created on Tue, 22 Nov 2022 17:10:57 GMT
   ✔  Approvals: 2
   ✔  - Moshe Atlow (@MoLow): https://github.com/nodejs/node/pull/45586#pullrequestreview-1191665656
   ✔  - Erick Wendel (@erickwendel): https://github.com/nodejs/node/pull/45586#pullrequestreview-1191845641
   ✔  Last GitHub CI successful
   ℹ  Last Full PR CI on 2022-12-01T16:56:08Z: https://ci.nodejs.org/job/node-test-pull-request/48266/
- Querying data for job/node-test-pull-request/48266/
   ✔  Last Jenkins CI successful
--------------------------------------------------------------------------------
   ✔  Aborted `git node land` session in /home/runner/work/node/node/.ncu

https://github.com/nodejs/node/actions/runs/3595374544

[nodejs-github-bot]

Landed in 2cad517