zeroize: `tests::zeroize_c_string` fails on i386

[innir]

Hi,

while testing zeroize on Debian infrastructure one test fails (it does not fail on other architectures).

---- tests::zeroize_c_string stdout ----
thread 'tests::zeroize_c_string' panicked at 'assertion failed: `(left == right)`
  left: `21`,
 right: `0`', src/lib.rs:936:17
stack backtrace:
   0: rust_begin_unwind
             at /usr/src/rustc-1.58.1/library/std/src/panicking.rs:498:5
   1: core::panicking::panic_fmt
             at /usr/src/rustc-1.58.1/library/core/src/panicking.rs:107:14
   2: core::panicking::assert_failed_inner
   3: core::panicking::assert_failed
             at /usr/src/rustc-1.58.1/library/core/src/panicking.rs:145:5
   4: zeroize::tests::zeroize_c_string
             at ./src/lib.rs:936:17
   5: zeroize::tests::zeroize_c_string::{{closure}}
             at ./src/lib.rs:922:5
   6: core::ops::function::FnOnce::call_once
             at /usr/src/rustc-1.58.1/library/core/src/ops/function.rs:227:5
   7: core::ops::function::FnOnce::call_once
             at /usr/src/rustc-1.58.1/library/core/src/ops/function.rs:227:5

Please find the full log at https://ci.debian.net/data/autopkgtest/testing/i386/r/rust-zeroize/22485575/log.gz

Any hints how to debug this?

[tarcieri]

It's possible this is a legitimate bug in the implementation. The functionality was recently added (#650) so it's relatively new. Is it sporadic or reproducible?

I would suggest adding some more assertions to the tests (e.g. is the original pointer changing?) to try to isolate the cause.

[tarcieri]

cc @robinhundt who authored #650

[innir]

From what I see the failure is reproducible - I just triggered a re-test, so we will know soon. As those builds are only done on Debian package upload it's not easily possible to debug it directly on this infrastructure ... but I think I could try the build/tests locally in a i386 qemu chroot if neede.

[innir]

Yes, it's reproducible, see https://ci.debian.net/packages/r/rust-zeroize/testing/i386/

[tarcieri]

That's good news. I'd suggest adding some more instrumentation (and possibly some dbg! statements) around the tests and see if we can observe anything unusual happening during those tests failures.

[robinhundt]

Yes, I think adding assert_eq!(cstring.as_bytes().as_ptr(), orig_ptr); after the call to cstring.zeroize(); would be a good idea. The backing Vec of the CString should not reallocate, but if that were the case, it might explain the failing test.

Another possibility is that the test case might contain UB and could be compiled to something unexpected for this target.

I also noticed that the tests are apparently run on a i386 CPU, but are compiled for the i686-unknown-linux-gnu target. Is this intended?

[innir]

I'll try - although, I'm not very fluent in Rust ... In Debian "i386" is the name of the x86 architecture, it now requires a i686 processor - so everything fine on this end.

[innir]

Running the test in a i386 chroot gave me this:

$ cargo --version
cargo 1.56.0
$ RUST_BACKTRACE=full cargo test --all-features

[...]

---- zeroize_c_string stdout ----
thread 'zeroize_c_string' panicked at 'assertion failed: `(left == right)`
  left: `21`,
 right: `0`', zeroize/tests/zeroize.rs:185:13
stack backtrace:
   0: 0x56625ab2 - std::backtrace_rs::backtrace::libunwind::trace::h320b03954b13b15a
                       at /usr/src/rustc-1.59.0/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1: 0x56625ab2 - std::backtrace_rs::backtrace::trace_unsynchronized::h404aa66a58afcce7
                       at /usr/src/rustc-1.59.0/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2: 0x56625ab2 - std::sys_common::backtrace::_print_fmt::h1f0df45566fa763e
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:67:5
   3: 0x56625ab2 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h49d2d68a197f5d73
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:46:22
   4: 0x566598d0 - core::fmt::write::h63f14257cbd95381
                       at /usr/src/rustc-1.59.0/library/core/src/fmt/mod.rs:1168:17
   5: 0x566442f5 - std::io::Write::write_fmt::h4c50e7f4adc5804d
                       at /usr/src/rustc-1.59.0/library/std/src/io/mod.rs:1660:15
   6: 0x5661d9c4 - std::sys_common::backtrace::_print::h5da1337f2a7da169
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:49:5
   7: 0x5661d9c4 - std::sys_common::backtrace::print::h2bb484354b6366ac
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:36:9
   8: 0x5661d9c4 - std::panicking::default_hook::{{closure}}::h60e5a8b70fb4684b
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:211:50
   9: 0x5661d5b8 - std::panicking::default_hook::hcb0fdf578cad4af3
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:225:9
  10: 0x5661df89 - std::panicking::rust_panic_with_hook::h173ed85a59f13a7c
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:606:17
  11: 0x5662631f - std::panicking::begin_panic_handler::{{closure}}::h14739303386c4688
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:502:13
  12: 0x56625bf4 - std::sys_common::backtrace::__rust_end_short_backtrace::hb6737ae7810b94dc
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:139:18
  13: 0x5661daae - rust_begin_unwind
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:498:5
  14: 0x565bf180 - core::panicking::panic_fmt::h91489b75f712f7b5
                       at /usr/src/rustc-1.59.0/library/core/src/panicking.rs:116:14
  15: 0x56654e5b - core::panicking::assert_failed_inner::h704e9e2e15fcef63
  16: 0x565cd47e - core::panicking::assert_failed::hd2ec6f0b6772109c
                       at /usr/src/rustc-1.59.0/library/core/src/panicking.rs:154:5
  17: 0x565c3e80 - zeroize::zeroize_c_string::h8dc7aeaf9dbd0fc1
                       at /utils/zeroize/tests/zeroize.rs:185:13
  18: 0x565c3b2d - zeroize::zeroize_c_string::{{closure}}::h46dde2f2e42da98e
                       at /utils/zeroize/tests/zeroize.rs:171:1
  19: 0x565cbbd1 - core::ops::function::FnOnce::call_once::hb28f778e64bc144e
                       at /usr/src/rustc-1.59.0/library/core/src/ops/function.rs:227:5
  20: 0x565d9852 - core::ops::function::FnOnce::call_once::h0572bae84892651f
                       at /usr/src/rustc-1.59.0/library/core/src/ops/function.rs:227:5
  21: 0x565d9852 - test::__rust_begin_short_backtrace::hd837b0aa16a9c015
                       at /usr/src/rustc-1.59.0/library/test/src/lib.rs:574:5
  22: 0x565d99bc - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h2e1dce8498d803b9
                       at /usr/src/rustc-1.59.0/library/alloc/src/boxed.rs:1854:9
  23: 0x565d99bc - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::hdf395b25b3e5c7c5
                       at /usr/src/rustc-1.59.0/library/core/src/panic/unwind_safe.rs:271:9
  24: 0x565d99bc - std::panicking::try::do_call::h16369fe0180352cd
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:406:40
  25: 0x565d99bc - std::panicking::try::h25f3cabb7fe2415f
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:370:19
  26: 0x565d99bc - std::panic::catch_unwind::hdb361248efc98a79
                       at /usr/src/rustc-1.59.0/library/std/src/panic.rs:133:14
  27: 0x565d99bc - test::run_test_in_process::hdd8fd07504e529c0
                       at /usr/src/rustc-1.59.0/library/test/src/lib.rs:597:18
  28: 0x565fd645 - test::run_test::run_test_inner::{{closure}}::ha9ae95d07ec41dcc
                       at /usr/src/rustc-1.59.0/library/test/src/lib.rs:491:39
  29: 0x565fd645 - test::run_test::run_test_inner::{{closure}}::h489e29cbdff688d7
                       at /usr/src/rustc-1.59.0/library/test/src/lib.rs:518:37
  30: 0x565fd645 - std::sys_common::backtrace::__rust_begin_short_backtrace::h7a7291046fe7c276
                       at /usr/src/rustc-1.59.0/library/std/src/sys_common/backtrace.rs:123:18
  31: 0x565fabb8 - std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}::h8e62180684017b8d
                       at /usr/src/rustc-1.59.0/library/std/src/thread/mod.rs:477:17
  32: 0x565fabb8 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h020046288dede4ff
                       at /usr/src/rustc-1.59.0/library/core/src/panic/unwind_safe.rs:271:9
  33: 0x565fabb8 - std::panicking::try::do_call::h4a6d763b94410ce3
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:406:40
  34: 0x565fabb8 - std::panicking::try::h7354ccdf46ae868d
                       at /usr/src/rustc-1.59.0/library/std/src/panicking.rs:370:19
  35: 0x565fabb8 - std::panic::catch_unwind::h28c94783f93fbaa6
                       at /usr/src/rustc-1.59.0/library/std/src/panic.rs:133:14
  36: 0x565fabb8 - std::thread::Builder::spawn_unchecked::{{closure}}::h51797d227a32d022
                       at /usr/src/rustc-1.59.0/library/std/src/thread/mod.rs:476:30
  37: 0x565fabb8 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h7a30731d70d141de
                       at /usr/src/rustc-1.59.0/library/core/src/ops/function.rs:227:5
  38: 0x5661560b - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h764764ad3dc9b175
                       at /usr/src/rustc-1.59.0/library/alloc/src/boxed.rs:1854:9
  39: 0x5661560b - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h5b9c09009d2e3828
                       at /usr/src/rustc-1.59.0/library/alloc/src/boxed.rs:1854:9
  40: 0x5661560b - std::sys::unix::thread::Thread::new::thread_start::heb638986cd3951cc
                       at /usr/src/rustc-1.59.0/library/std/src/sys/unix/thread.rs:108:17
  41: 0xf7f47e6c - start_thread
  42: 0xf7d43606 - clone
  43:        0x0 - <unknown>

Adding assert_eq!(cstring.as_bytes().as_ptr(), orig_ptr); doesn't change anything, it fails some lines further down https://github.com/RustCrypto/utils/blob/master/zeroize/tests/zeroize.rs#L185

[tarcieri]

FWIW I noticed we didn't have zeroize CI for 32-bit targets, although after adding it, it passed on an Ubuntu image:

https://github.com/RustCrypto/utils/pull/775

@innir if you have a QEMU recipe for reproducing it, can you post it and I can try to run it locally?

[innir]

Hm, most obvious difference is, I'm testing with --all-features and with rustc 1.59.0 ...

You can reproduce my chroot by this:

sudo mmdebstrap --arch=i386 --include=dh-cargo,git sid chroot-i386
sudo systemd-nspawn -D chroot-i386 git clone https://github.com/RustCrypto/utils.git
sudo systemd-nspawn --chdir /utils/zeroize -E RUST_BACKTRACE=full -D chroot-i386 cargo test --all-features

[innir]

@tarcieri Did you had any chance to reproduce the test failure?

[tarcieri]

Not as yet, unfortunately

Perhaps for now we can mark the test with #[ignore].

[tarcieri]

I've released zeroize v1.5.6 which adds #[ignore] to the flaky test.

However, I'm going to leave this issue open to track the test failure and whatever potential issues it may or may not be revealing

[robinhundt]

Mid to end of July, I'll have time to look at this at this issue as well, if it's not resolved until then.