tap gets confused with multiple tests providing timeout

[trentm]

First case: one test of four with a 'timeout' setting. Another test has a bogus config object ('xxx' key). This suite as expected.

var test = require('tap').test;
console.warn("[%s] Start.", new Date())
test("one", function(t) {
  t.ok("one", "one potato");
  t.end();
});
test("two", {timeout: 3000}, function(t) {
  setTimeout(function() {
    t.ok("two", "two potato");
    t.end()
    console.warn("[%s] Finished executing test two.", new Date())
  }, 7000);
});
test("three", {xxx: 1000}, function(t) {
  t.ok("three", "three potato");
  t.end();
});
test("four", function(t) {
  t.ok("four", "four");
  t.end();
});

output:

$ node foo.js 
[Mon Dec 05 2011 11:24:11 GMT-0800 (PST)] Start.
# one
ok 1 one potato
# two
not ok 2 Timeout!
  ---
    file:   timers.js
    line:   83
    column: 39
    stack:  
      - getCaller (/Users/trentm/src/node-tap/lib/tap-assert.js:376:17)
      - assert (/Users/trentm/src/node-tap/lib/tap-assert.js:17:16)
      - Function.fail (/Users/trentm/src/node-tap/lib/tap-assert.js:91:10)
      - Test._testAssert [as fail] (/Users/trentm/src/node-tap/lib/tap-test.js:86:16)
      - Test.timeout (/Users/trentm/src/node-tap/lib/tap-test.js:30:8)
      - Object._onTimeout (native)
      - Timer.callback (timers.js:83:39)
  ...
# three
ok 3 three potato
# four
ok 4 four

1..4
# tests 4
# pass  3
# fail  1
[Mon Dec 05 2011 11:24:18 GMT-0800 (PST)] Finished executing test two.

Second case: Both tests "two" and "three" have a timeout. We expect test two to timeout (as above) and test "three" to complete within its timeout:

var test = require('tap').test;
console.warn("[%s] Start.", new Date())
test("one", function(t) {
  t.ok("one", "one potato");
  t.end();
});
test("two", {timeout: 3000}, function(t) {
  setTimeout(function() {
    t.ok("two", "two potato");
    t.end()
    console.warn("[%s] Finished executing test two.", new Date())
  }, 7000);
});
test("three", {timeout: 1000}, function(t) {
  t.ok("three", "three potato");
  t.end();
});
test("four", function(t) {
  t.ok("four", "four");
  t.end();
});

output:

$ node foo.js 
[Mon Dec 05 2011 11:24:58 GMT-0800 (PST)] Start.
# one
ok 1 one potato
# two
not ok 2 Timeout!
  ---
    file:   timers.js
    line:   83
    column: 39
    stack:  
      - getCaller (/Users/trentm/src/node-tap/lib/tap-assert.js:376:17)
      - assert (/Users/trentm/src/node-tap/lib/tap-assert.js:17:16)
      - Function.fail (/Users/trentm/src/node-tap/lib/tap-assert.js:91:10)
      - Test._testAssert [as fail] (/Users/trentm/src/node-tap/lib/tap-test.js:86:16)
      - Test.timeout (/Users/trentm/src/node-tap/lib/tap-test.js:30:8)
      - Object._onTimeout (native)
      - Timer.callback (timers.js:83:39)
  ...
# three
not ok 3 Timeout!
  ---
    file:   timers.js
    line:   83
    column: 39
    stack:  
      - getCaller (/Users/trentm/src/node-tap/lib/tap-assert.js:376:17)
      - assert (/Users/trentm/src/node-tap/lib/tap-assert.js:17:16)
      - Function.fail (/Users/trentm/src/node-tap/lib/tap-assert.js:91:10)
      - Test._testAssert [as fail] (/Users/trentm/src/node-tap/lib/tap-test.js:86:16)
      - Test.timeout (/Users/trentm/src/node-tap/lib/tap-test.js:30:8)
      - Object._onTimeout (native)
      - Timer.callback (timers.js:83:39)
  ...
ok 4 three potato
not ok 5 end called more than once
  ---
    file:   /Users/trentm/src/node-tap/tmp/foo.js
    line:   33
    column: 5
    stack:  
      - getCaller (/Users/trentm/src/node-tap/lib/tap-assert.js:376:17)
      - assert (/Users/trentm/src/node-tap/lib/tap-assert.js:17:16)
      - Function.fail (/Users/trentm/src/node-tap/lib/tap-assert.js:91:10)
      - Test.end (/Users/trentm/src/node-tap/lib/tap-harness.js:102:29)
      - Test.<anonymous> (/Users/trentm/src/node-tap/tmp/foo.js:33:5)
      - Test.<anonymous> (native)
      - Test.<anonymous> (events.js:61:17)
      - Test.emit (/Users/trentm/src/node-tap/lib/tap-test.js:102:8)
      - GlobalHarness.<anonymous> (/Users/trentm/src/node-tap/lib/tap-harness.js:86:13)
      - Array.0 (native)
  ...
# four
ok 6 four

1..6
# tests 6
# pass  3
# fail  3
[Mon Dec 05 2011 11:25:05 GMT-0800 (PST)] Finished executing test two.

IOW, this does NOT work as expected.

On a possibly related note, you can see from the printed timestamps that the test run does not terminate until the 7s "setTimeout" still runs to completion. Say this is a test case that takes a crazy long time, or forever to complete. Ideally I'd want my run to be aborted after the timeout, but I don't know how I'd implement that in this case.

Third case: Extend the second timeout (for test "three") to 13s so that there is sufficient time after test "two" has timed out and completed as well. Code:

var test = require('tap').test;
console.warn("[%s] Start.", new Date())
test("one", function(t) {
  t.ok("one", "one potato");
  t.end();
});
test("two", {timeout: 3000}, function(t) {
  setTimeout(function() {
    t.ok("two", "two potato");
    t.end()
    console.warn("[%s] Finished executing test two.", new Date())
  }, 7000);
});
test("three", {timeout: 13000}, function(t) {
  t.ok("three", "three potato");
  t.end();
});
test("four", function(t) {
  t.ok("four", "four");
  t.end();
});

Result:

$ TAP=1 ./node_modules/.bin/tap foo.js
# one
ok 1 one potato
# two
not ok 2 Timeout!
# three
ok 3 three potato
# four
ok 4 four
# tests 4
# pass  3
# fail  1
ok 5 foo.js


1..5
# tests 5
# pass  4
# fail  1

I.e., this is as expected.

Theory: The timeout handling for each test case isn't correctly starting the count from when that test case itself is being run... but is starting from the start of the full test suite run (or rather the start of when this test file is being run if there are multiple test files being run).

[trentm]

Here is a fix: https://gist.github.com/1435149
I.e. only start the t.timeout setTimeout when the test starts running (i.e. at its "ready" event).

Isaac: does this look reasonable?