Panic (attempt to subtract with overflow) when calculating the number of passed_tests in utils\render_tests.rs

[anforowicz]

I apologize for not following the bug template + for not having a consistent repro. I hope that opening this issue will still help (writing down and sharing what we know, looping in the author of the line that panics, etc.).

It seems that when running rust tests on Windows, the test binary sometimes (flakily, inconsistently) panics saying (based on two cases when it happened recently - see here and here:

 �[1m�[32m     Running�[0m tests\builtin-clone.rs (build\x86_64-pc-windows-msvc\stage1-std\x86_64-pc-windows-msvc\release\deps\builtin_clone-92ab8a9329f9b62b.exe)
 
 running 1 tests
 
 thread 'main' panicked at src\bootstrap\src\utils\render_tests.rs:230:36:
 attempt to subtract with overflow
 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

So far this has only happened on Windows (and not on Linux). And it seems to only be happening when running tests from library/std/tests/builtin-clone.rs (which contain only a single testcase).

It seems that the line that panics has been introduced relatively recently (around a month ago) in dc11857#diff-218273cbe7a566fb9d2f12187307eb7fd0e4664abd7c375f0f4cd30183ea78c9R230:

```
let passed_tests = self.executed_tests - (self.failures.len() + self.ignored_tests);
```

I guess the panic indicates that self.executed_tests is smaller than the sum of self.failures.len() and self.ignored_tests. This seems rather unexpected.

FWIW This issue is tracked in Chromium's issue tracker as https://crbug.com/392978169.

[anforowicz]

/cc @ranger-ross from #135355

[ehuss]

It looks like there are multiple issues here.

One is that the stdout is getting corrupted because multiple threads are writing to it at once. You can see this here:

 C:\b\s\w\ir\cache\builder\src\third_party\rust-src\library\std>{ "type": "test", "name": "sync::mpsc::tests::oneshot_single_thread_try_send_closed", "event": "ok" }

bootstrap misses that JSON message because it got mixed with some other output. I don't know what is printing all that Microsoft Windows [Version 10.0.19045.5131] stuff.

The other issue is that Renderer is not resetting all its counters when it switches between suites. Currently it sets a few fields here like self.executed_tests. However, it does not clear self.ignored_tests or self.failures.

Because it missed one of the messages, it did not reach 100% in the percentage. When it runs the builtin-clone test, the executed_tests is 1, but ignored_tests is something like 5.

[ehuss]

The tests that are writing to the output are test_creation_flags and test_proc_thread_attributes. They are spawning cmd without capturing the output. I think those tests should be fixed to capture the output so it doesn't interfere with the JSON output.

There's still a bunch of other tests that are printing panic messages from spawned threads (like test_join_panic). I don't remember if the panic printing code locks stdout. If it does, then it is unlikely to interfere with the JSON output. If not, then it has some risk of having the same problem. (It also just makes the test output kinda noisy, but it might not be easy to avoid.)

[ehuss]

I'm going to reopen because there are two issues here. The other is that the counters never get reset between test suites, which means they can show incorrect results and possibly break in the same way depending on how the tests are organized.

[jieyouxu]

The other is that the counters never get reset between test suites, which means they can show incorrect results and possibly break in the same way depending on how the tests are organized.

@ehuss AFAIK they should be reset if we receive a new test suite start message now:

rust/src/bootstrap/src/utils/render_tests.rs

Lines 309 to 319 in 942db67

	fn render_message(&mut self, message: Message) {
	match message {
	Message::Suite(SuiteMessage::Started { test_count }) => {
	println!("\nrunning {test_count} tests");
	self.benches = vec![];
	self.failures = vec![];
	self.ignored_tests = 0;
	self.executed_tests = 0;
	self.terse_tests_in_line = 0;
	self.tests_count = Some(test_count);
	}

Did I miss anything? Or is there another example I can use to test?

[ehuss]

Oh, I'm sorry! I did not look at the PR, and I think the title got truncated on my thing and I just assumed it was just updating the tests. My bad!