Running into non-deterministic timeout in version 2.0.x

[AlessandroM92]

Dear folks,

I'm running into a non-deterministic timeout when using node-qunit-puppeteer version 2.0.0 - 2.0.3.

We've got 860 tests and 8300 assertions. The usual execution time is about 4 seconds. However, from time to time I get the following error:

PS C:\Source> ./node_modules/.bin/node-qunit-puppeteer wwwroot/indexDebug.html 20000
Target URL is file://C:\Source\wwwroot\indexDebug.html, timeout is 20000
Error: Test run could not finish in 20000ms
    at Timeout._onTimeout (C:\Source\node_modules\node-qunit-puppeteer\index.js:172:58)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)

My package.json looks like this:

"devDependencies": {
    "typescript": "3.8.3",
    "ts-loader": "7.0.5"
  },
  "dependencies": {
    "@progress/kendo-ui": "2020.2.617",
    "@types/jquery": "3.5.0",
    "@types/qunit": "2.9.1",
    "@types/kendo-ui": "2020.2.0",
    "bootstrap": "4.1.0",
    "jquery": "3.5.1",
    "node-qunit-puppeteer": "2.0.1",
    "@popperjs/core": "2.4.2",
    "qunit": "2.9.1",
    "tslib": "2.0.0",
    "typemoq": "2.1.0"
  },

When downgrading to version 1.1.1 that issue did not occur to me since then.

UPDATE: I debugged the unit test execution via node-qunit-puppeteer to figure out at which test it fails. It is during an async unit test using assert.async() and jQuery promises :jQueryPromise.done() + jQueryPromise.progress().

BR Alessandro

[ameshkov]

This means that DONE callback is never get called: https://github.com/ameshkov/node-qunit-puppeteer/blob/master/index.js#L80

Try patching node-qunit-puppeteer, add logging to all callbacks and at what exact test it gets stuck.

[AlessandroM92]

The exact test it gets stuck I already identified via debugging node-qunit-puppeteer.

Can you tell me how to debug the test itself via node-qunit-puppeteer. I did not manage to do so yet.

[ameshkov]

Well, you can't set a breakpoint inside the test because it's being run in a separate process.

You may try adding some console.log's in the test, but don't forget to set redirectConsole to true: https://github.com/ameshkov/node-qunit-puppeteer/blob/master/index.js#L163

[AlessandroM92]

Thanks to your advice I could identify the exact line after the problem occurs.

The callback "TEST_START_CB" is executed for the problematic test (https://github.com/ameshkov/node-qunit-puppeteer/blob/master/index.js#L122).

In my test I use the QUnit async feature: const done = assert.async(); I've got some other jQuery promises that are all called as expected. In the last jquery promise.done(() => {...}) callback I successfully call the QUnit done() function. And the line after I even logged that this was successful.

However, afterwards nothing happens anymore and the program runs into the timeout. The callback "TEST_DONE_CB" is never called for the problematic test (https://github.com/ameshkov/node-qunit-puppeteer/blob/master/index.js#L89).

[ameshkov]

Could it be a bug in QUint itself? Try adding QUint callbacks manually on your test page and check it in the browser.

[AlessandroM92]

JFYI: I've tried different versions (2.7.1 - 2.10.1) of qunit. The problem remains.

Try adding QUint callbacks manually on your test page and check it in the browser.

What do you exactly mean with manually adding the callbacks?

[ameshkov]

https://api.qunitjs.com/callbacks/QUnit.testDone/

[AlessandroM92]

Now it gets strange. If I log as the example suggests,

QUnit.testDone( function( details ) {
  var result = {
    "Module name": details.module,
    "Test name": details.name,
    "Assertions": {
      "Total": details.total,
      "Passed": details.passed,
      "Failed": details.failed
    },
    "Skipped": details.skipped,
    "Todo": details.todo,
    "Runtime": details.runtime
  };

  console.log( JSON.stringify( result, null, 2 ) );
} );

I receive the following behaviour.

Sometimes I run into a timeout after TEST_DONE_CB callback is called and the new log message is logged. In other times I run into a timeout before both TEST_DONE_CB and the new log is called/logged.

It also seems, the more I log to the console with redirectConsole=true the more timeouts occur.

[ameshkov]

Try reproducing this by running tests in the browser without using node-qunit-puppeteer at all

[AlessandroM92]

In the browser (Chrome version 84) I cannot reproduce this at all.

What I can observe is that QUnit takes some seconds to finish the execution of some async tests. However, it completes them.

[ameshkov]

There's one more thing you can try -- set QUnit.config.testTimeout to a smaller value - at least you'll easily figure out which test times out.

[AlessandroM92]

The recorded execution time of the problematic test is only about 40ms. I've got other fine running tests which consume 100ms or more.

Setting the testTimeout to 200ms does not help unfortunatly.

[ameshkov]

Well, I don't say it will solve the issue, but at least this test should be printed as failed in the node-qunit-puppeteer output.

So far, I am out of ideas on how to solve this without rewriting the problematic test :(

Meanwhile, one more question - is this the only async test you have?

[AlessandroM92]

No, I got a few async tests that fail on node-qunit-puppeteer execution from time to time. They all function similar with the assert.async() feature.

One thing that still occurs is if I log lots of messages while debugging in index.js and through redirectConsole=true I nearly always run into a timeout.

I've got a two options how to tackle the issue now:

• rewrite my affected unit tests
• use node-qunit-puppeteer 1.1.1

Thanks for the help. If you find a solution let me know! :)

[AlessandroM92]

I rewrote the tests so that I do not use assert.async(). Instead tried to solve it with and async test callback, basic promises and await. However, the sporadic timeouts still occur.

[Krinkle]

@AlessandroM92 If you can share a test case in a Gist or elsewhere, I'd be happy to help investigate. Or maybe share only one or two QUnit.test() cases where you used assert.async(), I might be able to tell what went wrong, and improve QUnit upstream to make that issue easier to detect.