GeezerVison is showing github.com — test: fix test-watch-mode-inspect by StefanStojanovic · Pull Request #45586 · nodejs/node
Conversation
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
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Uh oh!
There was an error while loading. Please reload this page.
|
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.
|
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Trott
added
the
request-ci
Add this label to start a Jenkins CI on a PR. Only starts once the PR has an approving review.
label
Nov 30, 2022
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Trott
commented
Dec 1, 2022
•
edited
Loading
Uh oh!
There was an error while loading. Please reload this page.
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.)
|
StefanStojanovic reacted with thumbs up emoji
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Trott
added
the
request-ci
Add this label to start a Jenkins CI on a PR. Only starts once the PR has an approving review.
label
Dec 1, 2022
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
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.
|
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
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 |
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
Sorry, something went wrong.
Uh oh!
There was an error while loading. Please reload this page.
This was referenced Dec 2, 2022
Reviewers
Trott
Trott approved these changes
MoLow
MoLow approved these changes
Uh oh!
There was an error while loading. Please reload this page.
Assignees
No one assigned
Labels
needs-ci
PRs that need a full CI run.
test
Issues and PRs related to Node.js core tests and test infrastructure.
watch-mode
Issues and PRs related to watch mode.
Milestone
No milestone
Development
Successfully merging this pull request may close these issues.
Uh oh!
There was an error while loading. Please reload this page.
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
|