observed setImmediate and setTimeout execution order contradicts documentation

[tristanls]

• Version: v6.2.1
• Platform: Darwin
• Subsystem: timers

Documentation for setImmediate:

Schedules "immediate" execution of callback after I/O events' callbacks and before timers set by setTimeout and setInterval are triggered.

Demonstration:

console.log("nodejs version", process.versions.node);
console.log("start");
setTimeout(() =>
{
    console.log("setTimeout 0 callback");
}, 0);
setTimeout(() =>
{
    console.log("setTimeout 1 callback");
}, 1);
setImmediate(() =>
{
    console.log("setImmediate callback");
});
setTimeout(() =>
{
    console.log("setTimeout 0 after setImmediate callback");
}, 0);
setTimeout(() =>
{
    console.log("setTimeout 1 after setImmediate callback");
}, 1);
process.nextTick(() => {
  console.log("nextTick callback");
});
console.log("scheduled");

Observed outputs:

$ node test.js 
nodejs version 6.2.1
start
scheduled
nextTick callback
setTimeout 0 callback
setTimeout 1 callback
setImmediate callback
setTimeout 0 after setImmediate callback
setTimeout 1 after setImmediate callback

$ node test.js 
nodejs version 6.2.1
start
scheduled
nextTick callback
setTimeout 0 callback
setTimeout 1 callback
setTimeout 0 after setImmediate callback
setTimeout 1 after setImmediate callback
setImmediate callback

Expected output:

$ node test.js 
nodejs version 6.2.1
start
scheduled
nextTick callback
setImmediate callback
setTimeout 0 callback
setTimeout 1 callback
setTimeout 0 after setImmediate callback
setTimeout 1 after setImmediate callback

[mscdex]

/cc @Fishrock123

[bnoordhuis]

I think this is a documentation issue. The documentation is correct about the order of events except at start-up, before node enters the event loop. If you wrap the test case in a setTimeout(), the order of events is as you would expect.

Worthwhile to point out: setTimeout(0) and setTimeout(1) are really the same thing, they both start a timer with a 1 millisecond timeout.

[tristanls]

Thank you for the explanation. I confirmed that wrapping in setTimeout(...) results in expected order.

[cjihrig]

@tristanls would you like to take a crack at improving the docs?

[tristanls]

@cjihrig I plan on doing so.

[blacksun1]

CC: @cjihrig, @tristanls

Hey guys,

I got tripped up on this issue today as well. I see that this documentation update wan't committed and looks like it has been forgotten about or just no one has had time to put it in.

Would you like me to have a crack at redoing this now that #6937 is in place?

Regards,

[blacksun1]

Wow, OK, I think that this is just broken as per the following

'use strict';

let immediateFired;
let numberOfIterations = 0;

// Handle any errors or rejections

process.on('uncaughtException', (err) => {
  console.error(`uncaughtException handled on iteration ${numberOfIterations}`)
  process.exit(1);
});

console.log(`Running test at ${new Date().toISOString()} on`, process.release, process.arch);

process.on('beforeExit', function() {

  immediateFired = 0;
  numberOfIterations++;
  setTimeout(main, 1);
});

function main() {

  setImmediate(() => {
    
    immediateFired++;
    // console.log('setImmediate 1 fired');
  });

  setTimeout(() => {
    
    if (immediateFired < 2) {
      throw new Error('setTimeout was fired before set immediate');
    }

    // console.log('setTimeout 1');
  }, 1);

  setImmediate(() => {
    
    immediateFired++;
    // console.log('setImmediate 2 fired');
  });
}

Basically, just run this code and my expectation is that it should just keep on running. In fact, what happens is after a random number of iterations it will stop with an error such as

➜  test node simplest.js
Running test at 2017-01-17T05:23:34.918Z on { name: 'node',
  sourceUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0.tar.gz',
  headersUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0-headers.tar.gz' } x64
uncaughtException handled on iteration 32
➜  test node simplest.js
Running test at 2017-01-17T05:23:35.563Z on { name: 'node',
  sourceUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0.tar.gz',
  headersUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0-headers.tar.gz' } x64
uncaughtException handled on iteration 2
➜  test node simplest.js
Running test at 2017-01-17T05:23:36.071Z on { name: 'node',
  sourceUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0.tar.gz',
  headersUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0-headers.tar.gz' } x64
uncaughtException handled on iteration 7
➜  test node simplest.js
Running test at 2017-01-17T05:23:36.532Z on { name: 'node',
  sourceUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0.tar.gz',
  headersUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0-headers.tar.gz' } x64
uncaughtException handled on iteration 66
➜  test node simplest.js
Running test at 2017-01-17T05:23:36.964Z on { name: 'node',
  sourceUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0.tar.gz',
  headersUrl: 'https://nodejs.org/download/release/v7.4.0/node-v7.4.0-headers.tar.gz' } x64
uncaughtException handled on iteration 58

I think that this is probably caused by issue Make setTimeout and setImmediate timers run consecutively #8460.

[jasnell]

@Fishrock123

[Fishrock123]

I think this is a documentation issue. The documentation is correct about the order of events except at start-up, before node enters the event loop. If you wrap the test case in a setTimeout(), the order of events is as you would expect.

@bnoordhuis That sounds like a bug to me. Is that because we execute startup in nextTick?

#8460 sounds like it may be potentially the actual problem, I probably did not recognize it because there was no testcase.