Panic in Receiver::recv()

[jamespharaoh]

I'm having a problem using a channel to send notifications to a background thread... As I understand it, this shouldn't be possible? Receiver::recv() is not supposed to panic, is it? I'm not doing anything unsafe...

Mentioned this on reddit and burntsushi has confirmed that this looks like a bug. I will try and produce some simpler code to reproduce this but don't have time at the moment. (edit - please nag me if i don't produce an example, I have a vague idea what will do it)

I've tried this with stable (1.14) and nightly and get the same result.

A copy of the code which generates the error is available here:

https://github.com/jamespharaoh/rust-output/tree/channel_recv_panic

thread '<unnamed>' panicked at 'internal error: entered unreachable code', ../src/libstd/sync/mpsc/mod.rs:879
stack backtrace:
   1:     0x55ab04830c1a - std::sys::imp::backtrace::tracing::imp::write::h917062bce4ff48c3
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x55ab0483672f - std::panicking::default_hook::{{closure}}::h0bacac31b5ed1870
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:247
   3:     0x55ab04834666 - std::panicking::default_hook::h5897799da33ece67
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:263
   4:     0x55ab04834d17 - std::panicking::rust_panic_with_hook::h109e116a3a861224
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:451
   5:     0x55ab045b4d73 - std::panicking::begin_panic::h634e2b37a96f78d4
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:413
   6:     0x55ab045b9ce0 - <std::sync::mpsc::Receiver<T>>::recv::h59b94a6df5881f84
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/macros.rs:44
   7:     0x55ab045e5ff3 - output::output_state::OutputState::background_thread::h8aaba65c8ed499f1
                        at /home/james/projects/storage/rust-output/src/output_state.rs:261
   8:     0x55ab045ea743 - output::output_state::OutputState::new::{{closure}}::hf69a0505c40cdaf3
                        at /home/james/projects/storage/rust-output/src/output_state.rs:79
   9:     0x55ab045dfeda - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::hb24d824e514ccbad
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panic.rs:295
  10:     0x55ab045b53d7 - std::panicking::try::do_call::h3a6460a838b6cf70
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:356
  11:     0x55ab0483e20a - __rust_maybe_catch_panic
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libpanic_unwind/lib.rs:97
  12:     0x55ab045b4eb6 - std::panicking::try::h3133aaaba181f2ff
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panicking.rs:332
  13:     0x55ab045b389e - std::panic::catch_unwind::h0d4cf58b5fb1c352
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/panic.rs:351
  14:     0x55ab045ea000 - std::thread::Builder::spawn::{{closure}}::h4fae90249c97a5c1
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/thread/mod.rs:287
  15:     0x55ab045ce9fe - <F as alloc::boxed::FnBox<A>>::call_box::hef839d7658cc4ef9
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:595
  16:     0x55ab04833d64 - std::sys::imp::thread::Thread::new::thread_start::ha102a6120fc52763
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/liballoc/boxed.rs:605
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys_common/thread.rs:21
                        at /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/obj/../src/libstd/sys/unix/thread.rs:84
  17:     0x7fc0c43506b9 - start_thread
  18:     0x7fc0c3e7082c - clone
  19:                0x0 - <unknown>

[alexcrichton]

@jamespharaoh do you have a standalone example for example that could be cargo run'd to reproduce? The code in that repository seems to just be a library?

[jamespharaoh]

I've attempted to recreate this in a simple piece of code but haven't had any success, will keep trying, but perhaps someone can give me some advice... I have a feeling this bug might be in some other synchronization that's going on, since I'm only creating one Sender and one Receiver, then the sender is passed around behind an Arc <Mutex>. These are being created in the main thread and passed to worker threads.

So it seems to me that somehow if part of the functionality to do that is not correctly synchronizing the state as this is cloned, locked, unlocked, and sent between threads, then it could certainly produce incorrect behaviour in the Sender behind it. Does that sound reasonable?

I am also using various C libraries etc but it seems unlikely that a problem with those would so reliably cause an error in the same place. Does this also seem reasonable?

[alexcrichton]

Yeah if there's other unsafe code that may be something to take a look at as well, but otherwise we haven't seen a segfault in channels in a very long time so nothing jumps to mind unfortunately :(

[jamespharaoh]

The other unsafe code is just compression libraries linked in, well trusted and heavily used, and accessed in a very threadsafe way. And despite lots of concurrency they work flawlessly - the only error I am seeing is always this same receiver issue.

My next experiment to reproduce it will add in another element from the app where i see the problem, which is your futures_cpupool library as a way of passing the Sender around. I will be back with results...

[alexcrichton]

Note that #40156 is similar to this so that makes me pretty confident it's not the fault of your local unsafe code. @jamespharaoh did you get anywhere with more investigation?

[jamespharaoh]

I haven't had a chance but will try soon.

[therustmonk]

I have a similar problem. recv_timeout panics
Sadness that I can't predict when it happens: the bug appears not every time.

                               at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:     0x56287ebb9a54 - std::sys_common::backtrace::_print::hd8a1b72dcf3955ef
                               at /checkout/src/libstd/sys_common/backtrace.rs:71
   2:     0x56287ebc149c - std::panicking::default_hook::{{closure}}::h5ff605bba7612658
                               at /checkout/src/libstd/sys_common/backtrace.rs:60
                               at /checkout/src/libstd/panicking.rs:355
   3:     0x56287ebc1064 - std::panicking::default_hook::h9bc4f6dfee57d6bd
                               at /checkout/src/libstd/panicking.rs:371
   4:     0x56287ebc18eb - std::panicking::rust_panic_with_hook::hdc01585dc2bf7122
                               at /checkout/src/libstd/panicking.rs:549
   5:     0x56287ebc17c4 - std::panicking::begin_panic::hf84f4975d9f9b642
                               at /checkout/src/libstd/panicking.rs:511
   6:     0x56287ebc16f9 - std::panicking::begin_panic_fmt::hcc3f360b2ba80419
                               at /checkout/src/libstd/panicking.rs:495
   7:     0x56287e3cbbc6 - <std::sync::mpsc::shared::Packet<T>>::decrement::he4fa9520181c5c85
                               at /checkout/src/libstd/macros.rs:51
   8:     0x56287e3c806f - <std::sync::mpsc::shared::Packet<T>>::recv::h3c95f5bc336537aa
                               at /checkout/src/libstd/sync/mpsc/shared.rs:232
   9:     0x56287e3ad379 - <std::sync::mpsc::Receiver<T>>::recv_max_until::h950909094e0767d9
                               at /checkout/src/libstd/sync/mpsc/mod.rs:966
  10:     0x56287e3acc85 - <std::sync::mpsc::Receiver<T>>::recv_timeout::hf72a64a0530efaa1
                               at /checkout/src/libstd/sync/mpsc/mod.rs:940
  11:     0x56287e466841 - <mould_extension::ConnectExtensionWorker as mould::worker::Worker<T>>::realize::hf8b7190433e70336
                               at /home/denis/vxrevenue/cloud/sub/mould-extension/src/lib.rs:129
  12:     0x56287e41cd77 - mould::server::process_session::{{closure}}::h0572e63ea7bd3be9
                               at /home/denis/vxrevenue/cloud/sub/mould/src/server.rs:83
  13:     0x56287e41b69a - mould::server::process_session::h54610d99cf99088f
                               at /home/denis/vxrevenue/cloud/sub/mould/src/server.rs:44
  14:     0x56287e41f76b - mould::server::wsmould::start::{{closure}}::hb36d2fb80ee5ded6
                               at /home/denis/vxrevenue/cloud/sub/mould/src/server.rs:272
  15:     0x56287e469345 - <std::panic::AssertUnwindSafe<F> as core::ops::FnOnce<()>>::call_once::h8ef904bc75108aeb
                               at /checkout/src/libstd/panic.rs:296
  16:     0x56287e3a2e7a - std::panicking::try::do_call::h0979d3031b45f486
                               at /checkout/src/libstd/panicking.rs:454
  17:     0x56287ebc897a - __rust_maybe_catch_panic
                               at /checkout/src/libpanic_unwind/lib.rs:98
  18:     0x56287e3a26de - std::panicking::try::h42b9334978084c46
                               at /checkout/src/libstd/panicking.rs:433
  19:     0x56287e39d4a3 - std::panic::catch_unwind::h5ea213ef0eb7edd1
                               at /checkout/src/libstd/panic.rs:361
  20:     0x56287e3a1a86 - std::thread::Builder::spawn::{{closure}}::h1288ffa1c4d83635
                               at /checkout/src/libstd/thread/mod.rs:360
  21:     0x56287e3fca66 - <F as alloc::boxed::FnBox<A>>::call_box::h1b125a486a246990
                               at /checkout/src/liballoc/boxed.rs:640
  22:     0x56287ebc0714 - std::sys::imp::thread::Thread::new::thread_start::h75b208405df6dcf1
                               at /checkout/src/liballoc/boxed.rs:650
                               at /checkout/src/libstd/sys_common/thread.rs:21
                               at /checkout/src/libstd/sys/unix/thread.rs:84
  23:     0x7f7d554096c9 - start_thread
  24:     0x7f7d54f2cf7e - clone
  25:                0x0 - <unknown>

[therustmonk]

Maybe it's important:

thread '<unnamed>' panicked at 'assertion failed: `(left == right)`
(left: `140664964694432`, right: `0`)', /checkout/src/libstd/sync/mpsc/shared.rs:503

https://doc.rust-lang.org/src/std/sync/mpsc/shared.rs.html#503

impl<T> Drop for Packet<T> {
    fn drop(&mut self) {
        // Note that this load is not only an assert for correctness about
        // disconnection, but also a proper fence before the read of
        // `to_wake`, so this assert cannot be removed with also removing
        // the `to_wake` assert.
        assert_eq!(self.cnt.load(Ordering::SeqCst), DISCONNECTED);
/*503*/ assert_eq!(self.to_wake.load(Ordering::SeqCst), 0); 
        assert_eq!(self.channels.load(Ordering::SeqCst), 0);
    }
}

[therustmonk]

Not only one thread panics. Other thread panics here:

    fn decrement(&self, token: SignalToken) -> StartResult {
        unsafe {
/*253*/     assert_eq!(self.to_wake.load(Ordering::SeqCst), 0);
            let ptr = token.cast_to_usize();
            self.to_wake.store(ptr, Ordering::SeqCst);

[therustmonk]

Hi @alexcrichton, I've made an example which often fails and sometimes panic! on receive:
https://github.com/DenisKolodin/rfail
It uses a lot of channels with short lifetime period. It works the following way:

1. spawn thread with hash-map which inserts or removes senders (like registration broker)
2. spawn thread which waits for registration, sends 2 requests and waits responses
3. it also spawned thread which registers itself and waits 2 request to respond them

To approve it panics I include trace I've taken:

thread '<unnamed>' panicked at 'assertion failed: `(left == right)` (left: `140671335870496`, right: `0`)', /checkout/src/libstd/sync/mpsc/shared.rs:253
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread '<unnamed>' panicked at 'sending request: "SendError(..)"', /checkout/src/libcore/result.rs:859
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Any', /checkout/src/libcore/result.rs:859

Sometimes it even loses messages and can be blocked.
I don't claim that my code don't contains bugs, but recv() must not panic! inside.

I hope it helps...

[therustmonk]

I've improved logging to make sure that the messages sends correctly. I saw a regularity: it brokes when sender instance moved (it transfers owning of the only one instance of Sender to HashMap). Сould the shared state be in an intermediate state during owning transfership and lose an internal state?

DEBUG:rfail: - - - - - - - - - - - - - - - - - - - -
DEBUG:rfail: >>>>> 716 >>>>>
DEBUG:rfail: 716 - found : 0
DEBUG:rfail: 716 - request -> 0
DEBUG:rfail: 716 - response <- 0
DEBUG:rfail: 716 - found : 1
DEBUG:rfail: 716 - request -> 1
DEBUG:rfail: 716 - response <- 1
DEBUG:rfail: 716 - found : 2
DEBUG:rfail: 716 - request -> 2
DEBUG:rfail: 716 - response <- 2
DEBUG:rfail: <<<<< 716 <<<<<
DEBUG:rfail: - - - - - - - - - - - - - - - - - - - -
DEBUG:rfail: >>>>> 717 >>>>>
DEBUG:rfail: 717 - found : 0
thread '<unnamed>' panicked at 'assertion failed: `(left == right)` (left: `139883544888960`, right: `0`)', /checkout/src/libstd/sync/mpsc/shared.rs:253
note: Run with `RUST_BACKTRACE=1` for a backtrace.
thread '<unnamed>' panicked at 'receive result: RecvError', /checkout/src/libcore/result.rs:859
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Any', /checkout/src/libcore/result.rs:859

Any ideas how can I detect, catch and debug it?

[alexcrichton]

@deniskolodin awesome thanks so much for the recent investigation into this!

The failure here I believe is specifically happening with finder and rbroker (the original channel). That's the only one which would have promoted itself to the shared.rs file. This is also pretty likely to be related to recv_timeout, but can you confirm that?

Locally I was unable to reproduce with RUST_LOG originally but with that env var set I've now been able to reproduce. Additionally I was also unable to reproduce once I locally replaced recv_timeout with recv. To me that implies that the bug is likely somewhere in abort_selection. I'll point out that selection over channels (a long since unstable feature) hasn't been as thoroughly tested as send and recv and the timeout infrastructure is using the same pieces as selection, so that may explain the instability!

It'd be great if you could help out investigating libstd in this regard, but I'll try to get around to taking a look too soon.

[therustmonk]

@alexcrichton I've checked it again with your suggestions. You are absolutely right: this bug appeared with recv_timeout only. I'll try to find it in shared.rs module...