[Feature Request] Add an optional callback/hook to log testContext on timeout

[sramam]

Description

Please consider adding a call back handler for test timeouts, to log test context before exiting.

Timeouts occur for many reasons - a few broad categories that come to mind:

1. Resource starvation on local machine.
2. Latency/communication black-hole to remote service
3. Incorrect expectation on response from remote service.
   (I'm sure there are others, these came to mind. Please do comment and I'll update the issue request as needed)

In my case, it's #3 I'm struggling with. An integration test has to wait for some log messages on a forked server. Since these occur out of order, this is a callback test, watching the stdout stream for the right messages.

Every time the server output changes (due to dev changes not out-of-order messages!),
this test fails - since the test assertions don't match.
However, since it's triggered on the streams data event, it now waits forever.
So I use a timeout to exit the test.

And there in lies the rub - the intermediate state is recorded and has valuable information, but has no way to be recorded for fault detection (within the AVA api).

Example code of the work-around and desired-interface are presented below.
The difference in line count is relatively small, however it took a while to surface the pattern and I imagine this is not all that much of an outlier use case.

Workaround

const TIMEOUT_IN_MS = 20000;
test.cb(`fork server and watch logs`, (t) => {
  const testContext  = {
   stdout: ``,
   stderr: ``,
  }; 
  const timer = setTimeout(() => {
    t.fail(JSON.stringify(testContext));
  }, TIMEOUT_IN_MS);

  const proc = exec(...);
  proc.stdout.on("data", (d) => {
    testContext.stdout = testContext.stdout.concat(d);
    if (testContext.stdout.split(`\n`).map((line) => line === expectedLog)) {
      clearTimeout(timer);
      proc.cancel();
      t.end();
    }
  });
});

Desired interface

const TIMEOUT_IN_MS = 20000;
test.cb(`fork server and watch logs`, (t) => {
  const testContext  = {
   stdout: ``,
   stderr: ``,
 };
 const expectedLog = `blah`;

 t.timeout(TIMEOUT_IN_MS, () => {
   t.fail(JSON.stringify(testContext));
 }) 

 const proc = exec(...);
 proc.stdout.on("data", (d) => {
   testContext.stdout = testContext.stdout.concat(d);
   if (testContext.stdout.split(`\n`).map((line) => line === expectedLog)) {
     proc.cancel();
     t.end();
   }
 });
});

[novemberborn]

Oh that's interesting!

We'll be landing an experimental implementation of #1692 soon. That could let you do something like this:

test('fork server and watch logs', async t => {
  const logs = []

  const attempt = await t.try(tt => {
    tt.timeout(2000)

    await new Promise(resolve => {
      const proc = exec()
      proc.stdout.on('data', chunk => {
        logs.push(chunk)
        proc.cancel()
        resolve()
      })
    })
  })

  if (attempt.failed) { // The timeout will cause the attempt to fail
    t.log(logs)
  }
  attempt.commit()
})

Please keep an eye on the releases and hopefully you'll give this a try. Would be great to hear your experiences with this.

(I'm closing this issue for housekeeping purposes, but let's keep the conversation going.)

[sramam]

@novemberborn, thanks for the pointer.

I finally read through the discussion on #1692, and really like the idea behind it - very useful for fuzz-testing. Will definitely use it.

Perhaps it's only me, but for the timeout use case, using the t.try mechanism strikes me as being a bit convoluted, in needing to understand both timeout needs and catching a test-failure within the test. I'd prefer the setTimeout workaround for it's simpler specification, making it much easier for future code readers to grok the authored intent.

The workaround is not all that onerous - one only has to remember clearTimeout(timer); in all the right places.

Perhaps it's a good idea to wait for more requests?

[novemberborn]

Perhaps it's a good idea to wait for more requests?

Agreed. In the meantime t.try() will provide a surface on which to do experiments, and then we can see what to support directly in AVA itself.