denoland / deno

A modern runtime for JavaScript and TypeScript.
https://deno.com
MIT License
96.47k stars 5.33k forks source link

Nondeterministic `deno test` output with Deno.exit() #25881

Open dandv opened 3 weeks ago

dandv commented 3 weeks ago

Running the following minimal reproduction code with deno test will not output the console.error message most of the time:

console.error('Error: API_KEY not set.');
Deno.exit(1);

This is a problem in real-life scenarios when tests should be aborted if setup conditions are not met.

Running it with deno run will output the message correctly:

image

I've looked at the documentation for Deno.exit() but don't see anything about leaks, and the test Sanitizers don't mention console.

deno 1.46.3 (stable, release, x86_64-unknown-linux-gnu)
v8 12.9.202.5-rusty
typescript 5.5.2
marvinhagemeister commented 3 weeks ago

Can confirm. It happens rarely for me on macOS, but it does happen. Made a script to repeatedly and every roughly 200th invocation prints a bunch of null characters instead of the expected output.

Screenshot 2024-09-27 at 15 39 20

Script I used:

#!/usr/bin/env bash
while :
do
    echo "-->" >> foo.log;
    NO_COLOR=1 deno test foo.test.ts >> foo.log;
    echo "<--" >> foo.log;
done

and foo.test.ts

console.error("Error: API_KEY not set.");
Deno.exit(1);
bartlomieju commented 3 weeks ago

This is raciness in thread synchronisation. When you console.log something it's sent to the main thread to be printed (to avoid interleaving of output) which can take a moment, but Deno.exit(1) exits the thread immediately leading to output like this.

marvinhagemeister commented 3 weeks ago

I don't think it's in the JS. I can also reproduce it by adding some log statements in the rust code in this method, but only when I have an eprintln! call with a format! argument which seems irrelevant. https://github.com/denoland/deno/blob/88a4f8dd97704b8905d05def949b137a75286b18/cli/tools/test/reporters/pretty.rs#L215

Added this into the method:

eprintln!("write: {}", format!("------- foo output -------"));
Screenshot 2024-09-27 at 16 06 42

If I do just this:

eprintln!("write: foo");

Then the output is correct.

Screenshot 2024-09-27 at 16 09 05

There definitely seems to be a race condition somewhere like you suggested, but it feels more like somewhere from Rust to me.

lucacasonato commented 2 weeks ago

We should probably fix this by intercepting top level Deno.exit() calls too, and sending them to the main thread to be handled (that way they can also respect --fail-fast and friends).