Intermittent test failures on master

[ralfbiedert]

While working on #666 I noticed that my cargo test is sometimes failing, even on master. However, not always the same tests fail, and they don't fail all the time.

The one I can most easily reproduce (about 20 - 30 out of 50 times I tried the last ~2h):

running 2 tests
thread '<unnamed>thread '' panicked at '<unnamed>boom' panicked at '', boomtests\iter_panic.rs', :tests\iter_panic.rs13::139:
9note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.

test iter_panic ... ok
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
test iter_panic_fuse ... FAILED

failures:

---- iter_panic_fuse stdout ----
thread 'iter_panic_fuse' panicked at 'assertion failed: count(iter.clone().panic_fuse().inspect(check).rev()) < expected', tests\iter_panic.rs:46:5


failures:
    iter_panic_fuse

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

Then there is, which happened once so far:

failures:

---- iter::test::check_partial_cmp_short_circuit stdout ----
thread 'iter::test::check_partial_cmp_short_circuit' panicked at 'assertion failed: counter.load(Ordering::SeqCst) < a.len()', src\iter\test.rs:479:5

Even when cargo test succeeds, I am still receiving something like this on the console during the run.

unning 2 tests
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
test iter_panic ... ok
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
thread '<unnamed>' panicked at 'boom', tests\iter_panic.rs:13:9
test iter_panic_fuse ... ok

I have a little bit the impression that once I wipe everything there is a higher chance that everything test the very first time, but I've only tried that 3-4 time so far, so that might be chance.

Things I tried:

• Copious amounts of cargo clean
• Running cargo test --release
• Manually removing target/
• Checking out a fresh git clone
• Wiping ~/.cargo and ~/.rustup

I am running

• stable-x86_64-pc-windows-msvc
• rustc 1.35.0 (3c235d560 2019-05-20)
• Microsoft (R) Incremental Linker Version 14.21.27702.2
• Windows 10 on a 9900k, 16 logical cores

On my Mac the tests seem to work.

Update - And I'm seeing the same issue on an old Windows notebook of mine witha fresh Rust install.

[alex8b]

Seeing this issue from another, unrelated Windows machine.

rustc 1.35.0 (3c235d560 2019-05-20)
stable-x86_64-pc-windows-msvc

Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz

	Base speed:	3.50 GHz
	Sockets:	1
	Cores:	6
	Logical processors:	12

[cuviper]

I'm not concerned about the "panicked at 'boom'" output in general. These tests are intentionally panicking, and Rust testing is imperfect about capturing output -- rust-lang/rust#42474.

But in the places where the tests actually fail, we do need to figure that out. It's interesting that this seems to be associated with Windows, as I'm not sure what would be OS specific here.

It's possible that these are just getting unlucky with iterator splits. Both of those tests are making assertions about short-circuiting, that we won't visit every item in the iterator. If it happens to split such that the triggering item is actually the last seen, then the short circuit behavior won't really have the desired effect.

So, I think these are just flaky tests, not a real problem. Fixing them may still be tricky.

[ralfbiedert]

Now that I think about it, this issue are two in one:

• There is at least one OS specific bug in the code
• The AppVeyor environment doesn't catch that bug on x86_64-pc-windows-msvc although it seems to be easy to provoke.

No idea about the bug.

About AppVeyor, maybe only runs the test on one core and doesn't provoke it? If so, it might be worthwhile to reconfigure the test runner to catch similar bugs in the future.

[cuviper]

A single-threaded "pool" would essentially run those tests in sequential order, which should be completely deterministic in succeeding. Maybe that is indeed what's helping AppVeyor, but I thought they did have multiple cores. (I'm already tempted to move all our platforms to a single CI though.)

[ralfbiedert]

Does the build / test output print the number of cores that were detected? If so the CI logs might tell that already somewhere.

[cuviper]

I don't see that in the logs: https://ci.appveyor.com/project/cuviper/rayon

But it looks like there should be at least 2 cores: https://www.appveyor.com/docs/build-environment/#build-vm-configurations

[Aaron1011]

I'm able to consistently reproduce this locally on x86_64-unknown-linux-gnu

[Aaron1011]

The problem appears to be that these assertions are fundamentally racy. They assume that a panic fairly early on will cause panic_fuse to stop early - however, this is not guaranteed to be the case. On a fast enough machine, all of the other items might be processed before the Fuse drop impl gets to run.