Ava: Initial timeout timer starts before tests are run

Created on 7 May 2017  路  5Comments  路  Source: avajs/ava

Run:
time ava --timeout 100 bug.js

The above command takes 30 seconds to run, I was expecting ava to fail the testcase after 100 milliseconds.

Another strange thing is that if I instead run:
time ava --timeout 1s bug.js
...then it exits after 1000ms as expected?!

Contents of bug.js is the following code:

import test from 'ava';

function getTheAnswerToTheMeaningOfLifeTheUniverseAndEverything(callback) {
    setTimeout(() => {
        // Forgetting to invoke callback here
    }, 30000);
}

test.cb('make sure callback is called exactly once', t => {
    t.plan(1);
    getTheAnswerToTheMeaningOfLifeTheUniverseAndEverything(result => {
        t.is(result, 42);
        t.end();
    });
});

Environment

ubuntu 15.10
node v7.7.2
npm 4.5.0
ava 0.19.1

bug help wanted scheduling

Most helpful comment

The problem is that we start the timeout before we launch the test workers. With a 100ms value it might trigger before any tests are ready to run, at which point it kinda gets lost.

I think instead we should track whether we have pending tests, and ensure the timer is running whenever new tests are started, clearing it when tests end. And assume that test workers aren't stuck in a while loop before they can notify the main process of their tests.

Regardless of the above, I don't think a value of 100ms is ever realistic given how AVA works. The designed use case of --timeout is to help catch hanging tests, not to limit how long a particular test can take. It'd be better to set the timeout to a few seconds instead.

(Possibly we could consider changing the value to always be in seconds?)

All 5 comments

The problem is that we start the timeout before we launch the test workers. With a 100ms value it might trigger before any tests are ready to run, at which point it kinda gets lost.

I think instead we should track whether we have pending tests, and ensure the timer is running whenever new tests are started, clearing it when tests end. And assume that test workers aren't stuck in a while loop before they can notify the main process of their tests.

Regardless of the above, I don't think a value of 100ms is ever realistic given how AVA works. The designed use case of --timeout is to help catch hanging tests, not to limit how long a particular test can take. It'd be better to set the timeout to a few seconds instead.

(Possibly we could consider changing the value to always be in seconds?)

(Possibly we could consider changing the value to always be in seconds?)

馃憤

The global timeout documentation makes it sound like the timer starts when the actual testcase starts, and also that the timer is reset whenever a new testcase begins (I think this sounds very sensible):
https://github.com/avajs/ava#global-timeout

In general, I think it's important that it's possible to:

  • detect bugs where an expected callback is never invoked
  • detect bugs where an expected callback is invoked two or more times
  • detect bugs where a synchronous function accidentally ends up in an infinite loop

Using Mocha I was able to cover all three use cases but I ended up adding an explicit timeout for each TC which has both pros and cons.

it('is working', function (done) {
  this.timeout(10000);

  util.asyncCallbackTrimLowThatAccidentallyCallsCallbackTwiceWhenBuggy('   Foo   ', actual => {
    assert.equal(actual, 'foo');
    done();
  });
});

I also implemented similar testcases in tape and qunit. Mocha and tape both make it look a bit like the testcase passed when the callback is invoked the first time. When the the extra, unexpected, call comes in it correctly fails the TC though, like this:
http://temp.minimum.se/screenshot_20170507_162344.png

The corresponding fail output from QUnit was less ambiguous:
http://temp.minimum.se/screenshot_20170507_162557.png

To catch all cases with ava I had to resort to a quite ugly hack:

test.cb('util test async callback function that forgets to callback', t => {
  t.plan(1);
  util.asyncCallbackTrimLowThatForgetsToCallbackWhenBuggy('   Foo   ', actual => {
    t.is(actual, 'foo');
  });
  // Ugly hack to make sure "missing / double callback" bugs are detected
  setTimeout(t.end, 500);
});

test.cb('util test async callback function that accidentally calls callback twice', t => {
  t.plan(1);
  util.asyncCallbackTrimLowThatAccidentallyCallsCallbackTwiceWhenBuggy('   Foo   ', actual => {
    t.is(actual, 'foo');
  });
  // Ugly hack to make sure "missing / double callback" bugs are detected
  setTimeout(t.end, 500);
});

It would be really sweet if there was a way to catch all three bug cases without resorting to the ugly hack.

The global timeout documentation makes it sound like the timer starts when the actual testcase starts, and also that the timer is reset whenever a new testcase begins

Yea. There's definitely a bug: we start the timer before we start collecting tests, and that's wrong.

In general, I think it's important that it's possible to:

  • detect bugs where an expected callback is never invoked

In specific scenarios we can already detect this even without the --timeout option. There are other scenarios where that's impossible though (say if your test sets up a persistent database connection).

  • detect bugs where an expected callback is invoked two or more times

We currently have no way of failing a test that passed previously, see #1330.

  • detect bugs where a synchronous function accidentally ends up in an infinite loop

Good point, this doesn't work. Opened #1378.


Let's continue discussion in the relevant issues. I'll change the title on this one to deal with the timer starting prematurely.

Yay, thanks for fixing!

Was this page helpful?
0 / 5 - 0 ratings

Related issues

sindresorhus picture sindresorhus  路  3Comments

clitetailor picture clitetailor  路  3Comments

leegee picture leegee  路  4Comments

nickjanssen picture nickjanssen  路  4Comments

electerious picture electerious  路  3Comments