Hi everyone, I’ve started working on this to learn more about the testing part of the codebase and would like to discuss my current approach (which can’t detect timeouts due to blocking operations) and how to implement the timeout handling in Rust.

The current problem

Currently, if a test’s promise never resolves, Deno will not execute any of the other tests within that file.

Imagine, for example, that you had the following file (a simplification of #13146):

// empty_event_loop_test.ts

function willResolve(shouldResolve: boolean): Promise<void> {
  return new Promise((resolve) => {
    if (shouldResolve) {
      resolve();
    }
  });
}

Deno.test("runs to completion", async () => {
  await willResolve(true);
});

Deno.test("never resolves", async () => {
  await willResolve(false);
});

Deno.test("never executed", () => {});

If you try to deno test this file, you will see that Deno only executes the first two tests.

➜ deno test
running 3 tests from file:///Users/lucasfcosta/deno_experiments/empty_event_loop_test.ts
test runs to completion ... ok (17ms)
test never resolves ...
test result: FAILED. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out (29ms)

error: Promise resolution is still pending but the event loop has already resolved.

Deno never executes the third test because the second test will cause a promise to be pending, but the stack and the event-loop will be empty, causing the runtime to throw an error while waiting for the runTests function to resolve.

https://github.com/denoland/deno/blob/340764adec4fd613239d8280664361b3c1b9d350/core/runtime.rs#L703-L712

As shown above, this error is thrown because the runtime polls v8 to see if there are pending promises but no tasks left in the event loop.

My current solution (detecting non-blocking timeouts)

My current approach can trigger timeouts that happen due to non-blocking operations, such as when promises never resolve (as shown in the example test file above).

First, I allowed a timeout to be specified in Deno.test, either through options or as an extra argument. That change enables users to specify timeouts in the following ways:

Deno.test({
    name: "never resolves",
    fn: async () => { await willResolve(false) },
    timeout: 5000
});

Deno.test("never resolves", async () => {
    await willResolve(false)
}, 5000);

Deno.test(function neverResolves() => {
    await willResolve(false)
}, 5000);

By default, the tests will use a timeout of 5000ms.

Then, when running the tests, we kick off a timer and immediately start executing the test. We then Promise.race the timer and the test’s result itself, using whichever resolves first as the test result.

for (const test of filtered) {
  // ...
  
  const timeout = new Promise((resolve) => setTimeout(() => {
    resolve({
      "failed": formatError(
        new TestTimeoutError(`Test timed out after ${test.timeout}ms`)
      )
    });
  }, test.timeout));

  const testExecution = runTest(test, description);
  const result = await Promise.race([testExecution, timeout]);
  
  // ...
  
  reportTestResult(description, result, elapsed);
}

⚠️ The problem with this approach is that it will not throw timeout errors for tests that perform blocking operations for longer than the specified timeout. The test below, for example, will cause deno test to hang.

Deno.test("blocking test", () => {
  while (true) {}
});

The ideal approach

As mentioned by @caspervonb, it would be much better to monitor a test’s execution from within the Rust runtime so that we could throw errors even when blocking operations cause a test to exceed a timeout.

Having read through the code, however, I believe there would be a significant amount of work to enable detecting timeout for individual synchronous tests.

For us to be able to timeout individual synchronous tests we’d need to change the unit of execution to that of a single test, not to runTests, which runs all tests for a specifier.

https://github.com/denoland/deno/blob/9872fbf189b7f843b15442731f2e18ffafc3a284/cli/tools/test.rs#L513-L522

We cannot timeout individual tests because the JS runtime which is running all of the specifier’s tests cannot be preempted to move forward once synchronous operations are in place. If there are synchronous operations happening, the stack never empties, and thus there’s no opportunity to pull anything from the event loop.

Timing out an entire specifier, however, is way easier. For that, we could simply start a timer as the test starts and, if the timer gets triggered before the test’s end, we terminate the specifier’s execution. When that happens, we then mark all remaining tests as having failed.

https://github.com/denoland/deno/blob/9872fbf189b7f843b15442731f2e18ffafc3a284/cli/tools/test.rs#L852-L854

⚠️ The problem with timing out the specifier as an whole is that its other tests will not run.

To summarise: if, from Rust’s point of view, the atomic unit of execution is a specifier, we can only time-out the entire specifier. On the other hand, if Rust is aware of individual tests (tests are the atomic unit of execution) we can then timeout individual tests.

Proposed way forward

Unless I’m missing something here, there seems to be no way of timing out a single synchronous test unless we coordinate the whole specifier execution within Rust, and delegate to JS only the execution of individual tests.

Considering how much work the aforementioned refactor would involve, I suggest we break down this issue into two:

1. Support timing out individual asynchronous tests (thus solving #13146)
2. Creating a separate PR to tackle timing out individual tests, which would require refactoring the atomic unit of work within Rust from a specifier to a single test-case

In case others have better ideas on how to detect and timeout individual synchronous tests, please let me know. I’m quite new to Deno and Rust, so I might not be aware of other ways of doing it, and I’m also keen to learn from others.

FYI, according to @mmastrac there are no more technical blockers to support this feature for both async and sync code (including sync hot-loops). I spoke with @nathanwhit about this and it’s been put in the backlog, but due to incoming Deno 2 release we might not have a bandwidth to address it for some time still.

This is completely untested and I’m not super familiar with web apis, but you might want to create a wrapper around AbortController that does the cleanup for you:

class TestTimeout {
  #timerId: ReturnType<typeof setTimeout>;
  #controller: AbortController;

  constructor(time: number) {
    this.#controller = new AbortController();
    this.#timerId = setTimeout(() => {
      this.#controller.abort();
    }, time);
  }

  [Symbol.dispose]() {
    clearTimeout(this.#timerId);
  }

  signal() {
    return this.#controller.signal;
  }
}

Then:

Deno.test('NRelay1.query', async () => {
  using timeout = new TestTimeout(1000);
  const relay = new NRelay1('wss://relay.mostr.pub');
  const events = await relay.query([{ kinds: [1], limit: 3 }], { signal: timeout.signal });

  assertEquals(events.length, 3);
  await relay.close();
});

Trying to work around this by passing AbortSignal.timeout(1000) into my potentially-long-running function. But when I do that Deno complains about leaky async ops:

Deno.test('NRelay1.query', async () => {
  const relay = new NRelay1('wss://relay.mostr.pub');
  const events = await relay.query([{ kinds: [1], limit: 3 }], { signal: AbortSignal.timeout(1000) });

  assertEquals(events.length, 3);
  await relay.close();
});

NRelay1.query => ./src/NRelay1.test.ts:8:6
error: Leaks detected:
  - An async operation to sleep for a duration was started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call.
To get more details where leaks occurred, run again with the --trace-leaks flag.

Unfortunately there is no easy way to get rid of the timeout attached to the AbortSignal when you create it with AbortSignal.timeout 🤷

If we do implement this, I think we should have a solution right away that works for both sync and async tests. A synchronous solution would also work for an async one.

I like Casper’s suggestion to show a warning like Rust. Perhaps it should show if it has been X seconds since the test started OR the last test step was reported.

We can time out individual tests easily by enumerating the deferred tests on the Rust side, I’ve added APIs in core to make this cleaner to do but the addition of the immediate mode steps API kind of borked all my plans to make the test runner any better and I can’t really progress forward with it at this point.

I’ve moved further development into my own runtime.