Investigate flaky test-vm-timeout.js

[Trott]

• Version: master
• Platform: CentOS 5 64-bit
• Subsystem: test vm

Example failure: https://ci.nodejs.org/job/node-test-commit-linux/3362/nodes=centos5-64/tapTestReport/test.tap-1025/

not ok 1025 test-vm-timeout.js
# FATAL ERROR: v8::FromJust Maybe value is Nothing.

[mscdex]

This same test recently failed on Windows, but with a different error:

not ok 267 parallel/test-vm-timeout
# vm.js:35
#     return realRunInContext.call(this, contextifiedSandbox, options);
#                             ^
# Error: Script execution interrupted.
#     at Error (native)
#     at ContextifyScript.Script.runInContext (vm.js:35:29)
#     at ContextifyScript.Script.runInNewContext (vm.js:41:15)
#     at Object.exports.runInNewContext (vm.js:72:17)
#     at context.runInVM (C:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-vm-timeout.js:29:10)
#     at evalmachine.<anonymous>:1:1
#     at ContextifyScript.Script.runInContext (vm.js:35:29)
#     at ContextifyScript.Script.runInNewContext (vm.js:41:15)
#     at Object.exports.runInNewContext (vm.js:72:17)
#     at C:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-vm-timeout.js:32:6

[addaleax]

That error message is due to #6635, but it doesn’t seem to make sense that it fails in this particular way in test-vm-timeout.js. I’m trying to reproduce this locally, but no success on Linux (x64 Ubuntu 16.04) so far.

[Trott]

This one has gotten relentless on Windows recently. /cc @nodejs/platform-windows @nodejs/testing

[Trott]

Looks like there's some hope/intention that #6734 will provide more information, but it looks like it currently prints the exact same backtrace we already have: https://ci.nodejs.org/job/node-test-binary-windows/2575/RUN_SUBSET=3,VS_VERSION=vcbt2015,label=win10/tapTestReport/test.tap-267/

[bnoordhuis]

@Trott It's not for augmenting JS stack traces (although I may do that in a follow-up PR) but it's for getting a meaningful C++ stack trace on fatal errors (e.g. the FATAL ERROR: v8::FromJust Maybe value is Nothing. you posted.)

[Trott]

@addaleax Your comment about #6635 refers to the Windows issue (with Script execution interrupted message) and not the Linux issue (with FATAL ERROR: v8::FromJust Maybe value is Nothing.), right?

You've probably noticed this but just in case: It's failing consistently this way on one (but only one!) of the Windows variations on CI and doesn't seem to fail this way anywhere else.

[Trott]

@nodejs/build Am I correct to observe that the Windows issue here is happening exclusively on the Azure hosts and never on the Rackspace hosts? Is there anything unusual about the Azure hosts that might cause a SIGINT to show up on Azure but not Rackspace, perhaps in some unexpected way? (Like maybe the terminal mode is in raw mode on Rackspace but not on Azure or something like that? I'm reaching here, but desperate times call for desperate uninformed rambling on GitHub. It's the law.)

[addaleax]

@Trott There’s a good chance the Windows issue is the Linux issue, my PR just changed the error message (because the assumption is that an interrupted script + no timeout indicated = received SIGINT). No part of test-vm-timeout installs any SIGINT handler, though.

[addaleax]

@Trott Could you try running a stress test or something with the outer timeout (line 32) increased from 100 to some significantly higher value, 100000 or so? It should not make the test run any longer than it does.

[joaocgreis]

This fails only in Windows 10 machines, which we have only in Azure and are quite slow. This fails with any compiles (actually, VCBT, the one used by normal CI for W10, seems to be the only one that makes it not fail sometimes). (Experiments here for reference)

@addaleax @Trott the test still fails with 150ms but I didn't see a failure with 200ms (tested a few times in one CI machine). We could rise this timeout to 1000ms or so. Would that make the test incorrect?

[Trott]

@joaocgreis I'm not familiar with this part of the code base so I definitely defer to @addaleax or @bnoordhuis on whether that's still a valid test. Seems it to me.

Ignorant speculation on my part, but maybe on a sufficiently slow Windows machine, the 10ms timeout and the 100ms timeout fire out of order (because it takes more than 100ms to get out of the current tick and now both timeouts are ready to fire?). So the outer vm times out first, and the inner vm hasn't yet set its timedout boolean to true or whatever, and it has code along the lines of:

if (timedout) {
    /* code that should run here but does not */ 
} else {
    /* code that actually runs here but shouldn't and assumes SIGINT */ 
}

[addaleax]

@Trott I can’t reproduce the bug locally (neither on Windows nor on Linux), at least with test-vm-timeout.js, but yeah, that makes a lot of sense, I should have a PR ready soon.