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...

[stepancheg]

FWIW, I've reduced @deniskolodin example to simpler one:

use std::thread;
use std::sync::Arc;
use std::time::Duration;
use std::sync::mpsc::channel;
use std::sync::atomic::AtomicUsize;
use std::sync::atomic::Ordering;

struct Barrier2 {
    c: Arc<AtomicUsize>,
}

impl Barrier2 {
    fn new() -> (Barrier2, Barrier2) {
        let a = Arc::new(AtomicUsize::new(0));
        (Barrier2 { c: a.clone() }, Barrier2 { c: a })
    }

    fn wait(&self) {
        self.c.fetch_add(1, Ordering::SeqCst);
        while self.c.load(Ordering::SeqCst) != 2 {
        }
    }
}

fn main() {
    for a in 0.. {
        println!("iter {}", a);

        let (a, b) = Barrier2::new();

        let (tx, rx) = channel();
        
        let th = thread::spawn(move || {
            a.wait();
            loop {
                match rx.recv_timeout(Duration::from_millis(1)) {
                    Ok(_) => {
                        break;
                    },
                    Err(_) => {
                    },
                }
            }
        });

        b.wait();
        thread::sleep(Duration::from_millis(1));
        tx.clone().send(()).expect("send");
        th.join().unwrap();
    }
}

In debug build it usually results in one of two assertions in 1000 iterations on my macbook.

[daniel-e]

I ran into the same problem. Here's a even easier example how to trigger the bug:

use std::sync::mpsc::channel;
use std::thread;
use std::time::Duration;

fn main() {
    let (tx, rx) = channel::<String>();

    thread::spawn(move || {
        let d = Duration::from_millis(10);
        loop {
            println!("recv");
            let _r = rx.recv_timeout(d);
        }
    });

    thread::sleep(Duration::from_millis(100));
    let _c1 = tx.clone();


    thread::sleep(Duration::from_secs(1));
}

[oberien]

@imnotbad ran into the same issue with a GTK project. I reduced the problem and investigated it. My reproduction case can be found in this playpen.

The problem is the following:
We start off with a oneshot or stream channel (it's the same for both). Now we recv_timeout on it. While that receive is running, the channel is upgraded to a shared. Due to having a (possibly blocking) receiver, the signal_token from the oneshot channel is moved over to the new shared channel (with inherit_blocker):

rust/src/libstd/sync/mpsc/mod.rs

Lines 871 to 876 in 7360d6d

	let sleeper = match p.upgrade(rx) {
	oneshot::UpSuccess |
	oneshot::UpDisconnected => None,
	oneshot::UpWoke(task) => Some(task),
	};
	a.inherit_blocker(sleeper, guard);

This results in the wake_token to be removed from the oneshot and put into the shared. If it was a blocking receive, this would be fine, because the next send on the shared channel is going to wake up the receiver, which will upgrade itself and receive the element on the shared receiver.
With recv_timeout, the receive call will timeout and call abort_selection, which would have removed the signal_token, if it wasn't moved already. The next receive (blocking or not) after the timeout assumes that the signal_token is 0, because there can only ever be a single consumer. That is not the case due to the reasons above, resulting in this assertion panicking:

rust/src/libstd/sync/mpsc/shared.rs

Lines 251 to 253 in 7360d6d

	fn decrement(&self, token: SignalToken) -> StartResult {
	unsafe {
	assert_eq!(self.to_wake.load(Ordering::SeqCst), 0);

My idea for a solution to the problem would be to remove the inheritage of the wake_token from the sender side. Instead after the sender has performed the upgrade, it should wake up the receiver, which cleans the signal_token, upgrades itself and registers a new signal_token.
While the current idea of not waking up the receiver might be slightly faster, I think that this solution is easier to implement. I would have tried to create a PR, but I'm not sure how to correctly initiate the shared channel, which currently is done like this when inheriting:

rust/src/libstd/sync/mpsc/shared.rs

Lines 100 to 128 in 7360d6d

	pub fn inherit_blocker(&self,
	token: Option<SignalToken>,
	guard: MutexGuard<()>) {
	token.map(|token| {
	assert_eq!(self.cnt.load(Ordering::SeqCst), 0);
	assert_eq!(self.to_wake.load(Ordering::SeqCst), 0);
	self.to_wake.store(unsafe { token.cast_to_usize() }, Ordering::SeqCst);
	self.cnt.store(-1, Ordering::SeqCst);
	// This store is a little sketchy. What's happening here is that
	// we're transferring a blocker from a oneshot or stream channel to
	// this shared channel. In doing so, we never spuriously wake them
	// up and rather only wake them up at the appropriate time. This
	// implementation of shared channels assumes that any blocking
	// recv() will undo the increment of steals performed in try_recv()
	// once the recv is complete. This thread that we're inheriting,
	// however, is not in the middle of recv. Hence, the first time we
	// wake them up, they're going to wake up from their old port, move
	// on to the upgraded port, and then call the block recv() function.
	//
	// When calling this function, they'll find there's data immediately
	// available, counting it as a steal. This in fact wasn't a steal
	// because we appropriately blocked them waiting for data.
	//
	// To offset this bad increment, we initially set the steal count to
	// -1. You'll find some special code in abort_selection() as well to
	// ensure that this -1 steal count doesn't escape too far.
	unsafe { *self.steals.get() = -1; }
	});

[daira]

Reading through this ticket, I strongly recommend that std::sync::mpsc be deprecated with a prominent warning in the API doc — probably suggesting to use crossbeam-channel. I only found this ticket by luck browsing through the docs for a function we didn't propose to use (recv_timeout), even though as far as I can see, the potential race conditions aren't limited to that function at all. There is an easily reproducible panic with recv_timeout, but the problems are with the entire library and are not avoidable.

If #93563 is going to be merged instead then fine, but there hasn't been any discussion of that since February.

[8573]

One alternative to crossbeam-channel could be zesterer/flume#18