libtest panics when running should_panic tests under QEMU armv7

[rossmacarthur]

This currently works on stable but now fails on beta and nightly.

I tried this code:

// lib.rs
#[cfg(test)]
mod tests {
    #[test]
    #[should_panic]
    fn it_works() {
        panic!("this test should pass");
    }
}

And used cross v0.2.1 to test it

$ cross -v +beta test --target armv7-unknown-linux-musleabihf
+ "rustc" "--print" "sysroot"
+ "rustup" "toolchain" "list"
+ "rustup" "target" "list" "--toolchain" "beta-x86_64-unknown-linux-gnu"
+ "rustup" "component" "list" "--toolchain" "beta-x86_64-unknown-linux-gnu"
+ "/usr/bin/docker" "run" "--userns" "host" "-e" "RUST_BACKTRACE" "-e" "PKG_CONFIG_ALLOW_CROSS=1" "--rm" "--user" "1000:1000" "-e" "XARGO_HOME=/xargo" "-e" "CARGO_HOME=/cargo" "-e" "CARGO_TARGET_DIR=/target" "-e" "USER=ross" "-e" "CROSS_RUNNER=" "-v" "/home/ross/.xargo:/xargo:Z" "-v" "/home/ross/.cargo:/cargo:Z" "-v" "/cargo/bin" "-v" "/home/ross/arm-test:/project:Z" "-v" "/home/ross/.rustup/toolchains/beta-x86_64-unknown-linux-gnu:/rust:Z,ro" "-v" "/home/ross/arm-test/target:/target:Z" "-w" "/project" "-i" "-t" "rustembedded/cross:armv7-unknown-linux-musleabihf-0.2.1" "sh" "-c" "PATH=$PATH:/rust/bin cargo -v test --target armv7-unknown-linux-musleabihf"
       Fresh arm-test v0.1.0 (/project)
    Finished test [unoptimized + debuginfo] target(s) in 0.01s
     Running `qemu-arm /target/armv7-unknown-linux-musleabihf/debug/deps/arm_test-6cdb46f45d2b6f28`

running 1 test
test tests::it_works ... thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"', src/libtest/lib.rs:556:30
error: test failed, to rerun pass '--lib'

I expected to see this happen: the test should pass and libtest should not panic.

Meta

rustc --version --verbose:

rustc 1.46.0-beta.2 (6f959902b 2020-07-23)
binary: rustc
commit-hash: 6f959902b3103c49ca981fbc01871589c3498489
commit-date: 2020-07-23
host: x86_64-unknown-linux-gnu
release: 1.46.0-beta.2
LLVM version: 10.0

Backtrace

$ RUST_BACKTRACE=full cross -v +beta test --target armv7-unknown-linux-musleabihf
+ "rustc" "--print" "sysroot"
+ "rustup" "toolchain" "list"
+ "rustup" "target" "list" "--toolchain" "beta-x86_64-unknown-linux-gnu"
+ "rustup" "component" "list" "--toolchain" "beta-x86_64-unknown-linux-gnu"
+ "/usr/bin/docker" "run" "--userns" "host" "-e" "RUST_BACKTRACE" "-e" "PKG_CONFIG_ALLOW_CROSS=1" "--rm" "--user" "1000:1000" "-e" "XARGO_HOME=/xargo" "-e" "CARGO_HOME=/cargo" "-e" "CARGO_TARGET_DIR=/target" "-e" "USER=ross" "-e" "CROSS_RUNNER=" "-v" "/home/ross/.xargo:/xargo:Z" "-v" "/home/ross/.cargo:/cargo:Z" "-v" "/cargo/bin" "-v" "/home/ross/arm-test:/project:Z" "-v" "/home/ross/.rustup/toolchains/beta-x86_64-unknown-linux-gnu:/rust:Z,ro" "-v" "/home/ross/arm-test/target:/target:Z" "-w" "/project" "-i" "-t" "rustembedded/cross:armv7-unknown-linux-musleabihf-0.2.1" "sh" "-c" "PATH=$PATH:/rust/bin cargo -v test --target armv7-unknown-linux-musleabihf"
       Fresh arm-test v0.1.0 (/project)
    Finished test [unoptimized + debuginfo] target(s) in 0.01s
     Running `qemu-arm /target/armv7-unknown-linux-musleabihf/debug/deps/arm_test-6cdb46f45d2b6f28`

running 1 test
test tests::it_works ... thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "PoisonError { inner: .. }"', src/libtest/lib.rs:556:30
stack backtrace:
   0:    0x580b4 - backtrace::backtrace::libunwind::trace::hd40b4f69fe271ed9
                       at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1:    0x580b4 - backtrace::backtrace::trace_unsynchronized::h3ca9a364f54e964e
                       at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2:    0x580b4 - std::sys_common::backtrace::_print_fmt::h982a8ae6b5f29f65
                       at src/libstd/sys_common/backtrace.rs:78
   3:    0x580b4 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::he8ccdc84a58ecc98
                       at src/libstd/sys_common/backtrace.rs:59
   4:    0x83040 - core::fmt::write::h23f93faacadec7cc
                       at src/libcore/fmt/mod.rs:1076
   5:    0x54940 - std::io::Write::write_fmt::haf0f338c5ed7de5f
                       at src/libstd/io/mod.rs:1537
   6:    0x5a88c - std::sys_common::backtrace::_print::h5683bffede5f926f
                       at src/libstd/sys_common/backtrace.rs:62
   7:    0x5a88c - std::sys_common::backtrace::print::h208a071bf789b7b7
                       at src/libstd/sys_common/backtrace.rs:49
   8:    0x5a88c - std::panicking::default_hook::{{closure}}::had93821ac17882da
                       at src/libstd/panicking.rs:198
   9:    0x5a558 - std::panicking::default_hook::ha27fdf8351cfa2f3
                       at src/libstd/panicking.rs:217
  10:    0x5af6c - std::panicking::rust_panic_with_hook::h5e82ec4b73107927
                       at src/libstd/panicking.rs:526
  11:    0x5ab6c - rust_begin_unwind
                       at src/libstd/panicking.rs:437
  12:    0x8170c - core::panicking::panic_fmt::h47be891d82598e44
                       at src/libcore/panicking.rs:85
  13:    0x81564 - core::option::expect_none_failed::h565bc8e7856c8fe7
                       at src/libcore/option.rs:1269
  14:    0x36e2c - core::result::Result<T,E>::unwrap::h916cdda944865138
                       at /rustc/6f959902b3103c49ca981fbc01871589c3498489/src/libcore/result.rs:1005
  15:    0x36e2c - test::run_test_in_process::h3c269a8ac50a2dd7
                       at src/libtest/lib.rs:556
  16:    0x36e2c - test::run_test::run_test_inner::{{closure}}::h15296ff2652b597f
                       at src/libtest/lib.rs:450
  17:    0x36424 - test::run_test::run_test_inner::hc9172a5fcccfeb6e
                       at src/libtest/lib.rs:475
  18:    0x34dd0 - test::run_test::h12bd73b7e259bc25
                       at src/libtest/lib.rs:505
  19:    0x264b4 - test::run_tests::ha1fdb36c7355f908
                       at src/libtest/lib.rs:284
  20:    0x264b4 - test::console::run_tests_console::he1caf03003813d3d
                       at src/libtest/console.rs:280
  21:    0x31b74 - test::test_main::hb716c54c676c2e08
                       at src/libtest/lib.rs:120
  22:    0x32c3c - test::test_main_static::hb9dfb706262f665b
                       at src/libtest/lib.rs:139
  23:    0x11970 - arm_test::main::he46c7a1e35416fc1
  24:    0x10f1c - std::rt::lang_start::{{closure}}::h250b51295a1aa3ab
                       at /rustc/6f959902b3103c49ca981fbc01871589c3498489/src/libstd/rt.rs:67
  25:    0x5b260 - std::rt::lang_start_internal::{{closure}}::h81f1dae74b28fcfc
                       at src/libstd/rt.rs:52
  26:    0x5b260 - std::panicking::try::do_call::ha6d54a9d8c9a8b73
                       at src/libstd/panicking.rs:348
  27:    0x5b260 - std::panicking::try::h018fe3feda747ef2
                       at src/libstd/panicking.rs:325
  28:    0x5b260 - std::panic::catch_unwind::hbcb5f8582e976c82
                       at src/libstd/panic.rs:394
  29:    0x5b260 - std::rt::lang_start_internal::h504aede73e26a7ed
                       at src/libstd/rt.rs:51
  30:    0x10ef0 - std::rt::lang_start::h5abd88271e1cf6f0
                       at /rustc/6f959902b3103c49ca981fbc01871589c3498489/src/libstd/rt.rs:67
  31:    0x119b8 - main
error: test failed, to rerun pass '--lib'

[rossmacarthur]

@rustbot modify labels: +A-libtest +O-ARM

[rossmacarthur]

I have noticed this issue as far back as nightly 4 Jun https://github.com/rossmacarthur/sheldon/runs/737733730. I disabled nightly armv7 tests on my project because of this. Filed this issue now because now it made its way into beta.

[LeSeulArtichaut]

Let’s try to bisect this.
@rustbot ping cleanup

[rustbot]

Hey Cleanup Crew ICE-breakers! This bug has been identified as a good
"Cleanup ICE-breaking candidate". In case it's useful, here are some
instructions for tackling these sorts of bugs. Maybe take a look?
Thanks! <3

cc @AminArria @camelid @chrissimpkins @contrun @DutchGhost @elshize @ethanboxx @h-michael @HallerPatrick @hdhoang @hellow554 @imtsuki @kanru @KarlK90 @LeSeulArtichaut @MAdrianMattocks @matheus-consoli @mental32 @nmccarty @Noah-Kennedy @pard68 @PeytonT @pierreN @Redblueflame @RobbieClarken @RobertoSnap @robjtede @SarthakSingh31 @senden9 @shekohex @sinato @spastorino @turboladen @woshilapin @yerke

[LeSeulArtichaut]

@rustbot ping arm

[rustbot]

Hey ARM Group! This bug has been identified as a good "ARM candidate".
In case it's useful, here are some instructions for tackling these sorts of
bugs. Maybe take a look?
Thanks! <3

cc @JamieCunliffe @joaopaulocarreiro @raw-bin @Stammark @vigoux

[JamieCunliffe]

According to cargo-bisect-rustc it appears to be caused by 6f48888

Although I haven't yet looked looked into this much more than that.

[LeSeulArtichaut]

It probably makes sense to have been caused by #72746 since that PR touches libunwind. cc @tmandry

[spastorino]

Assigning P-high as discussed as part of the Prioritization Working Group procedure and removing I-prioritize.

[nikomatsakis]

Could somebody reproduce this and print updated line numbers etc? Also, maybe run with RUST_BACKTRACE=1?

edit: I just realized the original report included a backtrace. Still probably good to get up to date numbers.

[nikomatsakis]

Although I'm guessing the error is now on line 559:

rust/library/test/src/lib.rs

Lines 555 to 560 in 1a7d9f5

	let test_result = match result {
	Ok(()) => calc_result(&desc, Ok(()), &time_opts, &exec_time),
	Err(e) => calc_result(&desc, Err(e.as_ref()), &time_opts, &exec_time),
	};
	let stdout = data.lock().unwrap().to_vec();
	let message = CompletedTest::new(desc, test_result, exec_time, stdout);

so really what is happening is that the lock is being poisoned by a panic somewhere else...

[nikomatsakis]

Is this specific to qemu?

[rossmacarthur]

I just ran this on a real armv7 device and the test runs correctly. So it could be specific to QEMU.

    Finished test [unoptimized + debuginfo] target(s) in 0.05s
     Running target/debug/deps/issue_74820-863cef64096af7fd

running 1 test
test tests::it_works ... ok

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

   Doc-tests issue-74820

running 0 tests

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

rustc 1.46.0-beta.4 (32c481e15 2020-08-09)
binary: rustc
commit-hash: 32c481e156c6431d2947d865bd2abc2315a931fc
commit-date: 2020-08-09
host: armv7-unknown-linux-gnueabihf
release: 1.46.0-beta.4
LLVM version: 10.0

[spastorino]

Lowering priority to P-medium as discussed during compiler team meeting

[tmandry]

If the lock is being poisoned by another panic we need to see what that one is. Consider building with -Cpanic=abort so we can see what's going on in the first panic. EDIT: Install a panic hook that prints the message for every panic, so we can see if there's another panic happening somewhere.

I don't see why the linked change would be causing something like this, but it's certainly possible.

[tmandry]

Oh nevermind, I skipped over the #[should_panic] test, panic=abort wouldn't work here.

There must be something misconfigured on this target. Something in libtest relying on libunwind symbols that used to be exported from libstd, perhaps? But why would it only happen on armv7?

[vojtechkral]

We've ran into a similar issue in the past: #65972
Any chance this might be the same thing / related?
I'd start by checking that libunwind build has all the defines it needs...

Edit: Doesn't look like that...

[Aaron1011]

It looks like panicking under QEMU is currently broken:

fn main() {
    panic!("This is a panic!");
}

gives:

thread 'main' panicked at 'This is a panic!', src/main.rs:2:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'assertion failed: state_and_queue & STATE_MASK == RUNNING', library/std/src/sync/once.rs:426:21
fatal runtime error: failed to initiate panic, error 9
Aborted (core dumped)

I tried manually updating the cargo-cross docker image to the latest QEMU (5.1.0), with the same result.

[vojtechkral]

Is this specific to qemu?

No, this happens on real hardware.

Install a panic hook that prints the message for every panic, so we can see if there's another panic happening somewhere.

When I add breakpoint at being_panic() in gdb I only just get that one panic in the test body.
It seems to me like the panic in the test is poisoning the I/O buffer mutex for some reason.
Edit: This is also corroborated by the fact that the error happens exactly the same with --test-threads 1.

Edit 2: Yes, the line number is correct, it happens in the line

let stdout = data.lock().unwrap().to_vec();

   0: rust_begin_unwind
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:475
   1: core::panicking::panic_fmt
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/panicking.rs:85
   2: core::option::expect_none_failed
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/option.rs:1221
   3: core::result::Result<T,E>::unwrap
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/result.rs:973
   4: test::run_test_in_process
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:559
   5: test::run_test::run_test_inner::{{closure}}
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:450
   6: test::run_test::run_test_inner
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:475
   7: test::run_test
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:505
   8: test::run_tests
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:284
   9: test::console::run_tests_console
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/console.rs:280
  10: test::test_main
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:120
  11: test::test_main_static
             at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/test/src/lib.rs:139

[raw-bin]

@vojtechkral : Please can you describe what hardware you see this on ?

[vojtechkral]

@raw-bin

# cat /proc/cpuinfo 
processor       : 0
model name      : ARMv7 Processor rev 0 (v7l)
BogoMIPS        : 1332.01
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpd32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x3
CPU part        : 0xc09
CPU revision    : 0

processor       : 1
model name      : ARMv7 Processor rev 0 (v7l)
BogoMIPS        : 1332.01
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpd32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x3
CPU part        : 0xc09
CPU revision    : 0

Hardware        : Xilinx Zynq Platform
Revision        : 0003
Serial          : 0000000000000000

[vojtechkral]

I recompiled the toolchain at the exact same version (1.47.0 - 18bf6b4), recompiled test program using that and the problem stopped appearing. I have a feeling this is going to be hard to debug.