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.

[lucasfcosta]

Hi @caspervonb, thank you for taking the time to clarify 💖

I totally see how we could enumerate the deferred tests on the Rust side, but those would only be non-blocking tests, correct? I totally agree we should time out async tests in Rust rather than in JS as I've done in my example, but I still can't see how we would time-out individual blocking tests within a specifier.

Consider, for example, a file with the following contents:

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

Deno.test("non-blocking test", () => {});

In this case, because Rust invokes runTests, which runs the whole specifier, I can't see how we would timeout blocking test but still execute non-blocking test. Considering both are running in the same isolate, we'd have to timeout the entire specifier, wouldn't we? Or is there another way for us to preempt that thread and continue from non-blocking test?

That's why I thought that we could have different isolates/threads per test: so that we could timeout individual tests.

[caspervonb]

but those would only be non-blocking tests, correct?

The test handler runs on its own thread by design so timeouts, amongst other things can still be handled.

In this case, because Rust invokes runTests, which runs the whole specifier, I can't see how we would timeout blocking test

Even with a single isolate one could call terminate execution in v8, and then continue with the next test. Bad state can of course have a cascading effect if you write your tests in a leaky manner but not really a concern of the runner.

Another path is to simply do nothing and print warnings ala "hey this test is hanging after " with no side effects. Simple is often better, this is what libtest (cargo test) does.

[lucasfcosta]

As discussed on Discord, I started implementing a simple timeout handled in the JS runtime as described in my previous comment.

For future reference, here's what we discussed:

@lucasfcosta
How do folks feel about:
a) submitting a PR which simply fixes the timeout for async tests (in the simple way described in the PR) - just to fix the current problem
b) Performing the refactor so that we can timeout all tests (including sync) within Rust
Or should we just go straight to B?

@bartlomieju
Option A is fine. But 5000 ms default timeout is way too small. There's a lot of tests in Deno or deno_std that spawn subprocesses that take way longer in debug builds. I think 60s for default is fine. However what would happen if test times out? I feel like you'll be getting sanitizer errors, but maybe that's a problem for another day

After implementing the async timeout, I'll start working on a separate PR for reporting a timeout warning for synchronous tests using Rust, as @caspervonb suggested.

Yep, my preferred approach is simply to report a timeout warning the reporter
Infinite loops are still infinite loops, but they're detected.
Rust's libtest does the same thing

[dsherret]

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.

[skybrian]

[...] 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.

I think this would be a good idea. Rust should start a JavaScript interpreter and tell it to run each test one at a time.

This could also be used to run tests in parallel, using multiple JavaScript interpreters. If one test is slow or hangs, only one interpreter is affected and the other tests can keep going.

It also might be a way to improve isolation between tests. When a test fails, throw away that JavaScript interpreter and create another one, so it can't affect any other tests. (For performance, it might be good to have a spare interpreter ready.)

There could be a "maximum paranoia" mode where Rust only runs one test in an interpreter before throwing it away. However, that would be slow when there's a lot of initialization before an interpreter can start running the first test.

[vsDizzy]

I'm sharing my solution:

import { afterEach, beforeEach } from 'std/testing/bdd.ts'

function withTimeout(timeoutMs = 5000) {
  let timeoutId: number

  beforeEach(() => {
    timeoutId = setTimeout(() => {
      throw new Error(`Timed out after ${timeoutMs} ms.`)
    }, timeoutMs)
  })

  afterEach(() => {
    clearTimeout(timeoutId)
  })
}

[alexgleason]

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 🤷

[dsherret]

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();
});

[bartlomieju]

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.