"thread '<unnamed>' panicked" on unit tests

[behnam]

Following up the problem we faced in https://github.com/servo/unicode-bidi/pull/40, I'm able to repro the problem consistently on Ubuntu 12.04.5 with latest nightly rust.

Here's the repro:

~/code/rust-unicode-bidi$ RUST_BACKTRACE=1 RUST_TEST_THREADS=1 cargo +nightly test --verbose --lib --features flame_it -- --nocapture >/dev/null
       Fresh matches v0.1.6
       Fresh serde v1.0.8
       Fresh libc v0.2.23
       Fresh winapi-build v0.1.1
       Fresh winapi v0.2.8
       Fresh lazy_static v0.2.8
       Fresh serde_test v1.0.8
       Fresh kernel32-sys v0.2.2
       Fresh thread-id v2.0.0
       Fresh flame v0.1.11
       Fresh flamer v0.1.4
       Fresh unicode-bidi v0.3.3 (file:///home/behnam/code/rust-unicode-bidi)
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
     Running `/home/behnam/code/rust-unicode-bidi/target/debug/deps/unicode_bidi-f20b46f3613e37fb --nocapture`
thread '<unnamed>' panicked at 'use of std::thread::current() is not possible after the thread's local data has been destroyed', /checkout/src/libcore/option.rs:823
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace

The failure is caused by the std::thread::current() expecting thread dat to not be destroyed: https://doc.rust-lang.org/1.3.0/src/std/thread/mod.rs.html#409

Basically, when flame (and flamer) are enabled, a thread panics at the ends of the test. (The tests themselves all pass with ok message.) Without flame/flamer crates loaded, there's no panic.

Crate dependency tree is:

├── flame v0.1.11
│   ├── lazy_static v0.2.8
│   └── thread-id v2.0.0
│       ├── kernel32-sys v0.2.2
│       │   └── winapi v0.2.8
│       └── libc v0.2.23

I'm guessing that the bug is somewhere under thread-id. (cc @ruuda)

I haven't been able to repro it in any later Ubuntu version. I'll report if and when I can.

[ruuda]

thread_id::get() does not contain any significant code, it just calls GetCurrentThreadID() on Windows or pthread_self() on Unix-ish platforms. There is no way in which those could panic, as those are non-Rust functions. Thread local data sounds more like a problem with lazy_static (or maybe incorrect use thereof).

[behnam]

Okay, confirmed that cargo test fails for flame on Ubuntu 12.04:

behnam@ubuntu-12:~/code/flame$ RUST_BACKTRACE=full RUST_TEST_THREADS=1 cargo +nightly test --verbose -- --nocapture >/dev/null
       Fresh itoa v0.3.1
       Fresh num-traits v0.1.39
       Fresh unicode-xid v0.0.4
       Fresh dtoa v0.4.1
       Fresh quote v0.3.15
       Fresh serde v1.0.8
       Fresh libc v0.2.23
       Fresh lazy_static v0.2.8
       Fresh synom v0.11.3
       Fresh serde_json v1.0.2
       Fresh thread-id v3.1.0
       Fresh syn v0.11.11
       Fresh serde_derive_internals v0.15.1
       Fresh serde_derive v1.0.8
       Fresh flame v0.1.11 (file:///home/behnam/code/flame)
    Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
     Running `/home/behnam/code/flame/target/debug/deps/flame-841c60338d9dc705 --nocapture`
     Running `/home/behnam/code/flame/target/debug/deps/tests-b96fc7fd8d17e1ec --nocapture`
thread 'cant_note' panicked at 'flame::note(hi, None) called without a currently running span!', src/lib.rs:407
stack backtrace:
   0:     0x7fb1d5ccfcc3 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::hf6993ec76a3b39d8
                               at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x7fb1d5cccd04 - std::sys_common::backtrace::_print::h3d630ba2218f7ec3
                               at /checkout/src/libstd/sys_common/backtrace.rs:71
   2:     0x7fb1d5cd28ca - std::panicking::default_hook::{{closure}}::hd0df6de62c549847
                               at /checkout/src/libstd/sys_common/backtrace.rs:60
                               at /checkout/src/libstd/panicking.rs:355
   3:     0x7fb1d5cd237d - std::panicking::default_hook::h9bbcc81c50b40ea3
                               at /checkout/src/libstd/panicking.rs:371
   4:     0x7fb1d5cd2cdb - std::panicking::rust_panic_with_hook::hcb9f41173fe183d3
                               at /checkout/src/libstd/panicking.rs:549
   5:     0x7fb1d5cd2b64 - std::panicking::begin_panic::h6af6db04028173d3
                               at /checkout/src/libstd/panicking.rs:511
   6:     0x7fb1d5cd2ae9 - std::panicking::begin_panic_fmt::h2ea6b56a88fe4f9f
                               at /checkout/src/libstd/panicking.rs:495
   7:     0x7fb1d5c7ae1b - flame::note::{{closure}}::h7f34e67675b580ab
                               at /home/behnam/code/flame/<panic macros>:8
   8:     0x7fb1d5c74537 - <std::thread::local::LocalKey<T>>::with::h793b0f0a852b9bcc
                               at /checkout/src/libstd/thread/local.rs:265
   9:     0x7fb1d5c7ab0f - flame::note::h3098e6b44d99e163
                               at /home/behnam/code/flame/src/lib.rs:399
  10:     0x7fb1d5c8002b - tests::cant_note::hb937f8d35cb86bab
                               at tests/tests.rs:126
  11:     0x7fb1d5c9e0d1 - <F as test::FnBox<T>>::call_box::h157505cd95d7f68b
                               at /checkout/src/libtest/lib.rs:1451
                               at /checkout/src/libcore/ops/function.rs:143
                               at /checkout/src/libtest/lib.rs:140
  12:     0x7fb1d5cd9c7a - __rust_maybe_catch_panic
                               at /checkout/src/libpanic_unwind/lib.rs:98
  13:     0x7fb1d5c92273 - std::sys_common::backtrace::__rust_begin_short_backtrace::hbcb5f6d27cb567a7
                               at /checkout/src/libstd/panicking.rs:433
                               at /checkout/src/libstd/panic.rs:361
                               at /checkout/src/libtest/lib.rs:1390
                               at /checkout/src/libstd/sys_common/backtrace.rs:136
  14:     0x7fb1d5c93032 - std::panicking::try::do_call::h487da3d3b47ef904
                               at /checkout/src/libstd/thread/mod.rs:364
                               at /checkout/src/libstd/panic.rs:296
                               at /checkout/src/libstd/panicking.rs:454
  15:     0x7fb1d5cd9c7a - __rust_maybe_catch_panic
                               at /checkout/src/libpanic_unwind/lib.rs:98
  16:     0x7fb1d5c98fcc - <F as alloc::boxed::FnBox<A>>::call_box::hf6bc90a905d6274b
                               at /checkout/src/libstd/panicking.rs:433
                               at /checkout/src/libstd/panic.rs:361
                               at /checkout/src/libstd/thread/mod.rs:363
                               at /checkout/src/liballoc/boxed.rs:648
  17:     0x7fb1d5cd19b5 - std::sys::imp::thread::Thread::new::thread_start::h9e7dc9c59c04ba25
                               at /checkout/src/liballoc/boxed.rs:658
                               at /checkout/src/libstd/sys_common/thread.rs:21
                               at /checkout/src/libstd/sys/unix/thread.rs:84
  18:     0x7fb1d5413e99 - start_thread
  19:     0x7fb1d4f2a73c - <unknown>
thread '<unnamed>' panicked at 'use of std::thread::current() is not possible after the thread's local data has been destroyed', /checkout/src/libcore/option.rs:823
stack backtrace:
   0:     0x7fb1d5ccfcc3 - std::sys::imp::backtrace::tracing::imp::unwind_backtrace::hf6993ec76a3b39d8
                               at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x7fb1d5cccd04 - std::sys_common::backtrace::_print::h3d630ba2218f7ec3
                               at /checkout/src/libstd/sys_common/backtrace.rs:71
   2:     0x7fb1d5cd28ca - std::panicking::default_hook::{{closure}}::hd0df6de62c549847
                               at /checkout/src/libstd/sys_common/backtrace.rs:60
                               at /checkout/src/libstd/panicking.rs:355
   3:     0x7fb1d5cd237d - std::panicking::default_hook::h9bbcc81c50b40ea3
                               at /checkout/src/libstd/panicking.rs:371
   4:     0x7fb1d5cd2cdb - std::panicking::rust_panic_with_hook::hcb9f41173fe183d3
                               at /checkout/src/libstd/panicking.rs:549
   5:     0x7fb1d5cd2b64 - std::panicking::begin_panic::h6af6db04028173d3
                               at /checkout/src/libstd/panicking.rs:511
   6:     0x7fb1d5cd2ae9 - std::panicking::begin_panic_fmt::h2ea6b56a88fe4f9f
                               at /checkout/src/libstd/panicking.rs:495
   7:     0x7fb1d5cd2a77 - rust_begin_unwind
                               at /checkout/src/libstd/panicking.rs:471
   8:     0x7fb1d5cfc6dd - core::panicking::panic_fmt::h883a028e9f4b4457
                               at /checkout/src/libcore/panicking.rs:69
   9:     0x7fb1d5cfc74d - core::option::expect_failed::h1ff823102004902d
                               at /checkout/src/libcore/option.rs:823
  10:     0x7fb1d5cc6351 - std::thread::current::hdde8aec72047b2c5
                               at /checkout/src/libcore/option.rs:302
                               at /checkout/src/libstd/thread/mod.rs:516
  11:     0x7fb1d5c8f18d - flame::commit_impl::h9b16fa1fb496e47b
                               at src/lib.rs:272
  12:     0x7fb1d5c8f39c - <flame::Library as core::ops::drop::Drop>::drop::hd08f2b743c9d7d9e
                               at src/lib.rs:283
  13:     0x7fb1d5c88604 - core::ptr::drop_in_place::h7802a89084952cd1
                               at /checkout/src/libcore/ptr.rs:60
  14:     0x7fb1d5c88d14 - core::ptr::drop_in_place::hd4b00cc6bd2c883b
                               at /checkout/src/libcore/ptr.rs:60
  15:     0x7fb1d5c88488 - core::ptr::drop_in_place::h6d432efd487eceaa
                               at /checkout/src/libcore/ptr.rs:60
  16:     0x7fb1d5c88209 - core::ptr::drop_in_place::h4ca31a44392a6119
                               at /checkout/src/libcore/ptr.rs:60
  17:     0x7fb1d5c83c33 - std::sys::imp::fast_thread_local::destroy_value::hdfedfaa367f2d26e
                               at /checkout/src/libstd/sys/unix/fast_thread_local.rs:172
  18:     0x7fb1d5cd04fe - std::sys::imp::fast_thread_local::register_dtor_fallback::run_dtors::h247ee46ef4b5f0ad
                               at /checkout/src/libstd/sys/unix/fast_thread_local.rs:92
  19:     0x7fb1d5413c82 - __nptl_deallocate_tsd
  20:     0x7fb1d5413ea7 - start_thread
  21:     0x7fb1d4f2a73c - <unknown>
fatal runtime error: failed to initiate panic, error 5
error: process didn't exit successfully: `/home/behnam/code/flame/target/debug/deps/tests-b96fc7fd8d17e1ec --nocapture` (signal: 6, SIGABRT: process abort signal)

[behnam]

So, it's caused in this line: https://github.com/TyOverby/flame/blob/master/src/lib.rs#L272

let thread_name = ::std::thread::current().name().map(Into::into);

Turns out, the drop() impl (which calls into commit_impl()) gets called after the current thread is destroyed.

@TyOverby, what do you think?

[behnam]

Apparently it repros on all linux and has been failing on all recent travis jobs: https://travis-ci.org/TyOverby/flame/builds/242944913

[TyOverby]

Turns out, the drop() impl (which calls into commit_impl()) gets called after the current thread is destroyed.

That sounds like a pretty serious safety violation either by the rust compiler, or the lazy_static library.

I'll try to get access to an ubuntu machine so that I can debug this further.

[TyOverby]

Fixed in #21