timer,domain: timers don't maintain order after exception

[bnoordhuis]

var domain = require('domain').create();

domain.run(function() {
  setTimeout(function() { throw Error('FAIL'); }, 1);
  setTimeout(function() { console.log('timeout 1'); }, 1);
  setTimeout(function() { console.log('timeout 2'); }, 2);
});

domain.once('error', function() {});

Expected output:

timeout 1
timeout 2

Actual output:

timeout 2
timeout 1

(EDIT: I forgot to mention that you may need to run the test a few times.)

[petkaantonov]

FWIW:

io.js makes no guarantees about the exact timing of when the callback will fire, nor of the ordering things will fire in

[Fishrock123]

It still points to larger problems within the timers impl though.

[petkaantonov]

Yes I definitely think that timers should guarantee order to the extent that browsers do, currently they don't do that even in normal code (normal as in not using domains) and code that assumes e.g. setTimeout(..., 5) fires before setTimeout(..., 1000).is broken in node but works fine in browsers.

[Fishrock123]

I'm pretty sure this has something to do with the fact that after an error timers.js re-schedules to start processing again on the next tick, but doesn't actually stop processing presently: https://github.com/nodejs/io.js/blob/master/lib/timers.js#L100

This diff fixes the test, but causes other problems, so I'm confused.

diff --git a/lib/timers.js b/lib/timers.js
index 494c599..67b7a7a 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -99,6 +99,7 @@ function listOnTimeout() {
           process.domain = null;
           process.nextTick(listOnTimeoutNT, list);
           process.domain = oldDomain;
+          return;
         }
       }
     }

if you're curious, here's the error log from make test (8 errors): https://gist.github.com/Fishrock123/ad3e50ac7e4e76740c3e

[Fishrock123]

Also, is it possible this only happens when the list gets processed at a time when all 3 should fire in the same tick? (i.e. >2ms)

[trevnorris]

Just to add to this confusion, here's a slight change to the test script:

'use strict';
const domain = require('domain').create();
const print = process._rawDebug;

domain.run(function() {
  setTimeout(function() { throw Error('FAIL') }, 1);
  setTimeout(function() { print('timeout 1') }, 1);
  setImmediate(function() { print('immediate 1') });
  setTimeout(function() { print('timeout 2') }, 2);
  setImmediate(function() { print('immediate 2') });
});

domain.once('error', function() {});

I've gotten the output of:

timeout 2  
timeout 1  
immediate 1
immediate 2

and

immediate 1
immediate 2
timeout 1  
timeout 2  

[jasnell]

@trevnorris @bnoordhuis ... running this against master currently, given about 100 runs each on @bnoordhuis' original and @trevnorris' revised version and I'm not seeing any variability in the ordering over timer events. Could this one have been fixed?

[Fishrock123]

Strange. I'll investigate soon.

[jasnell]

btw, ran the tests on OSX in case it happens to matter. Have not tried the same tests against v5 or v4 yet.

[Fishrock123]

Looks like I can still reproduce, at about the same rate.

Make sure you use a command looper. Here's a modified test to accommodate that.

const domain = require('domain').create();
var first = false;

domain.run(function() {
  setTimeout(function() { throw Error('FAIL'); }, 1);
  setTimeout(function() {
    first = true;
    console.log('timeout 1');
  }, 1);
  setTimeout(function() {
    console.log('timeout 2');
    if (first === false) {
      console.log('timers reordered!')
      process.exit(1);
    }
  }, 2);
});

domain.once('error', function() {});

... shell scripts: (fish-shell & bash)

while ../node/node timers-reorder.js
end

while ../node/node timers-reorder.js; do :; done