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

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.)

FWIW:

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

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

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.

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

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)

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

@trevnorris

@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?

Strange. I'll investigate soon.

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

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

@imyller

Just repo'd on OS X 10.10.5. @imyller did you try my test case on repeat?

Maybe we should just call this "one of those odd domain bugs", close the issue, and call it a day.

Or I could spend like a week debugging it but that is probably not a good use of my time.

@Fishrock123

did you try my test case on repeat?

@Fishrock123 Yes, I just let it loop with shell while-do on OS X 10.11.6 and couldn't reproduce.

With Linux test environment this is very easy to reproduce with only few repeats.

Your call, but I personally wouldn't close the issue yet because the reproduceable problem still exists and the cause is not yet understood.

@misterdjules

I suppose. I suspect unless someone else throws a considerable amount of time at it, this will just go away when domains are likely removed in a couple years.

I'm able to help with the timers side of things if anyone wants to take a look into it.

Maybe @misterdjules would actually be the best to take a look?

I took a crack at this and hopefully what I found is useful :-)
The callbacks are stored in an associative array that is indexed by the number of milliseconds.
So list[1] is created for 1ms callbacks, and list[2] is created for 2ms callbacks.
Both these lists are in the queue for the current tick.
When list[1] encounters an unhandled exception, only the 1ms list is postponed to the next tick.
However, list[2] still exists on the current tick and will go through.

The solution seems to be skip all further list[x] to the next tick.
I tested this on linux and all tests pass. Also the test case in the first comment prints the timers in order.
jBarz@e93c751

@jBarz

@jBarz that sounds reasonable, could you submit a PR?

Hmmmm that does actually make sense now that I think about it.

@Fishrock123

I added @Fishrock123 's test case from #1271 (comment)
Without the looping though. So it runs only once.

Fixed by 9dac165

timer,domain: maintain order of timer callbacks

Navigation Menu

Repository navigation

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

2 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

petkaantonov commented on Mar 26, 2015

Fishrock123 commented on Mar 26, 2015

petkaantonov commented on Mar 26, 2015

Fishrock123 commented on Jul 24, 2015

Fishrock123 commented on Jul 24, 2015

trevnorris commented on Feb 8, 2016

jasnell commented on Apr 19, 2016

Fishrock123 commented on Apr 19, 2016

jasnell commented on Apr 19, 2016

Fishrock123 commented on May 2, 2016

2 remaining items

Fishrock123 commented on Sep 17, 2016

imyller commented on Sep 17, 2016

Fishrock123 commented on Sep 17, 2016

jBarz commented on Dec 29, 2016

gibfahn commented on Dec 29, 2016

Fishrock123 commented on Dec 29, 2016

jBarz commented on Dec 29, 2016

Fishrock123 commented on Feb 15, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions