Repository navigation
Regression in setImmediate() on Windows starting from Node.js 10.2.0 #21210
Description
- Version: 10.2.0 (x86, x64)
- Platform: Windows 10 PRO version 1607 build 14393.2214 64-bit OS, x64-based OS,
but also the virtual images uses by AppVeyor, see e.g. this build outcome.
Please note that MacOS and Linux are not affected, at least according to our Travis CI run (link). - Subsystem:
High level instructions to reproduce the problem:
git clone https://github.com/strongloop/loopback-next.git
git checkout 9788bf6342
npm install
npm run build:current
cd packages/cli
npm test
On Node.js 10.1.0 (Win32/x86), the tests pass. On Node.js 10.2.0 and newer, the tests hang in such way that the Node.js process cannot be terminated from the terminal using Ctrl+C when invoking mocha directly, bypassing the npm wrapper. Both 10.2.0/x86 and 10.2.0/x64 are showing this problem.
I managed to track down the problem to grouped-queue module (used by yeoman which we use in our CLI), see https://github.com/SBoudrias/grouped-queue/blob/6909aa1b49f607c218ed79b5e372221f18ea8792/lib/subqueue.js#L41-L44
SubQueue.prototype.run = function( skip, done ) {
if ( this.__queue__.length === 0 ) return skip();
setImmediate( this.shift().task.bind(null, done) );
};I have instrumented the code to print debug logs to console.
SubQueue.prototype.run = function( skip, done ) {
if ( this.__queue__.length === 0 ) return skip();
console.log('SCHEDULING SUBTASK');
setImmediate(() => {
console.log('GOING TO RUN SUBTASK');
this.shift().task(done);
});
};This is printed before the process hangs - notice that we call setImmediate but the callback is never called by Node.
SCHEDULING SUBTASK
GOING TO RUN SUBTASK
SCHEDULING SUBTASK
When I change setImmediate to process.nextTick, the problem goes away and tests pass once again even on Node.js 10.2.0.
SubQueue.prototype.run = function( skip, done ) {
if ( this.__queue__.length === 0 ) return skip();
console.log('SCHEDULING SUBTASK');
process.nextTick(() => {
console.log('GOING TO RUN SUBTASK');
this.shift().task(done);
});
};
Activity
[-]Regression in setImmediate() starting from Node.js 10.2.0 on Win32[/-][+]Regression in setImmediate() on Windowns starting from Node.js 10.2.0 [/+][-]Regression in setImmediate() on Windowns starting from Node.js 10.2.0 [/-][+]Regression in setImmediate() on Windows starting from Node.js 10.2.0 [/+]addaleax commentedon Jun 8, 2018
/cc @apapirovski
apapirovski commentedon Jun 8, 2018
There were no changes to Immediates or timers in 10.2.0. I can try to debug later today.
apapirovski commentedon Jun 8, 2018
Also the fact that this is Windows only would indicate the problem is somewhere else in the testing code.
targos commentedon Jun 8, 2018
I'm unable to reproduce with Node 10.3.0. The process doesn't hang. Instead, tests fail like this (end of output):
apapirovski commentedon Jun 9, 2018
I only have access to one Windows VM and I can't reproduce. I'm still pretty certain this would not be a regression in
setImmediateas nothing about it changed in 10.2.0. I'm guessing something about the timing in the tests changed (via changes to another subsystem) and hencenextTickstill succeeds, butsetImmediatedoesn't.apapirovski commentedon Jun 9, 2018
@Trott please, no... 😂
Trott commentedon Jun 9, 2018
I deleted my comment, but @apapirovski's comment above makes no sense now without it, so here it was (more or less):
@apapirovski Maybe it has something to do with garbage collection?
Just kidding.
Or am I???!!!
bajtos commentedon Jun 11, 2018
Thank you all for looking into this issue ❤️
The test fails because of debugging console logs which I added to troubleshoot the issue and which our test setup rejects. The fact that it runs to completion and does not hang is the signal we are looking for.
To be honest, I am not sure if
setImmediateis the real root cause of the problem. I though it is a likely cause because when I changedsetImmediatetoprocess.nextTick, the problem went away (at least on my local machine, which is a Win10 image in VirtualBox hosted on MacOS).It's rather unfortunate that others are not able to reproduce the problem. I guess it hints on a timing issue?
To move this forward: is there any faster way to identify the cause than compiling Node.js from source and running
git bisectto find the offending commit? If not, then I'll roll up my sleeves and do that tedious work.apapirovski commentedon Jun 11, 2018
That could just mean the timing of some other code changed and it's sensitive to being run in a specific place in the event loop.
The setImmediate code is very basic and has no chance of race conditions or OS specific behaviours.
apapirovski commentedon Jun 11, 2018
Also your console.logs above indicate the callback is called, so it's clearly the task itself not triggering thedonecallback.Actually I see what you mean, the second callback. It's possible you somehow get stuck in an infinite loop in a nextTick. Which is why the code works when switched to nextTick.
bajtos commentedon Jun 11, 2018
I don't think so. The console logs indicate that
setImmediatewas called twice, but the callback was fired only once.apapirovski commentedon Jun 11, 2018
Here's a quick test: try using
setTimeout(this.shift().task.bind(null, done), 1)and see if it still hangs or not. If it doesn't, try with a value like 100 instead of 1.bajtos commentedon Jun 11, 2018
FWIW: I am not able to reproduce the problem on a physical machine running Windows 10 (Node.js 10.4.0/x64). The problem manifests only when Windows is running in a virtualized environment.
bajtos commentedon Jun 11, 2018
Bummer. After a very recent Windows update, I am not able to reproduce the problem in my VirtualBox either. I'd like to try few more things before this issue can be closed as invalid.
revert: pin Node.js 10.x version to 10.0.0
revert: pin Node.js 10.x version to 10.0.0
revert: pin Node.js 10.x version to 10.0.0
revert: pin Node.js 10.x version to 10.0.0
revert: pin Node.js 10.x version to 10.0.0