Deno.test() should support timeout option

[bartlomieju]

Deno.TestDefinition should allows to specify a timeout for a test case:

Deno.test({
   name: "some net test",
   timeout: 5000 // in ms
   async fn() {
      //
   }
});

[caspervonb]

We had a PR for this quite a while back (#7372).

[caspervonb]

Landed in std denoland/std#1022

import { deadline } from "https://deno.land/std/async/mod.ts";

Deno.test("footer", deadline(async function() {
}, 400);

[bartlomieju]

I still think this should be built-in option to test definition instead of requiring to import it from deno_std.

[caspervonb]

I still think this should be built-in option to test definition instead of requiring to import it from deno_std.

If we do it from Rust, so that even blocking operations time out then sure sgtm.

[bartlomieju]

I still think this should be built-in option to test definition instead of requiring to import it from deno_std.

If we do it from Rust, so that even blocking operations time out then sure sgtm.

That sounds good - we could discover code blocking forever - at first glance it looks like we'd need 3 separate threads for that - main ("coordinator") thread, timeout thread and thread running test code. Any ideas for implementation?

[caspervonb]

I still think this should be built-in option to test definition instead of requiring to import it from deno_std.

If we do it from Rust, so that even blocking operations time out then sure sgtm.

That sounds good - we could discover code blocking forever - at first glance it looks like we'd need 3 separate threads for that - main ("coordinator") thread, timeout thread and thread running test code. Any ideas for implementation?

Yeah I already tried this in the refactor that I punted, should be even cleaner to do that now with resolve_value which I was doing inline 🙂

[lucasfcosta]

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.

deno/core/runtime.rs

Lines 703 to 712 in 340764a

	if let Ok(promise) = v8::Local::<v8::Promise>::try_from(local) {
	match promise.state() {
	v8::PromiseState::Pending => match state {
	Poll::Ready(Ok(_)) => {
	let msg = "Promise resolution is still pending but the event loop has already resolved.";
	Poll::Ready(Err(generic_error(msg)))
	},
	Poll::Ready(Err(e)) => Poll::Ready(Err(e)),
	Poll::Pending => Poll::Pending,
	},

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.

deno/cli/tools/test.rs

Lines 513 to 522 in 9872fbf

	let test_result = worker.js_runtime.execute_script(
	&located_script_name!(),
	&format!(
	r#"Deno[Deno.internal].runTests({})"#,
	json!({
	"filter": options.filter,
	"shuffle": options.shuffle,
	}),
	),
	)?;

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.

deno/cli/tools/test.rs

Lines 852 to 854 in 9872fbf

	TestEvent::Wait(description) => {
	reporter.report_wait(&description);
	}

⚠️ 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 deno test exits prematurely if a test empties the event loop #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.

[caspervonb]

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.