Mavulp/pokebot

Bot sometimes disconnects

Closed this issue · 4 comments

One worker thread seems to get stuck on gst_element_send_event() in pokebot::audio_player::AudioPlayer::stop_current().
One was waiting for epoll_wait from libc and the last one was waiting for a std::sync::mpsc::Receiver<T>::recv().

Full example of a backtrace (gstreamer/log4rs threads not listed).

Thread 1 has target name 'pokebot'
Thread 3 has target name 'tokio-runtime-w'
Thread 4 has target name 'tokio-runtime-w'
Thread 5 has target name 'tokio-runtime-w'
Thread 12 has target name 'tokio-runtime-w'

Thread 1 (Thread 0x7f4eaf70adc0 (LWP 3345325)):
#0  0x00007f4eafcd7c45 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x000055838d92703d in futures::task_impl::std::ThreadNotify::park ()
#2  0x000055838d2d294e in tokio_executor::enter::Enter::block_on ()
#3  0x000055838d30191e in pokebot::main ()
#4  0x000055838d309c03 in std::rt::lang_start::{{closure}} ()
#5  0x000055838d93ddc3 in std::rt::lang_start_internal::{{closure}} () at src/libstd/rt.rs:48
#6  0x000055838d93ddc3 in std::panicking::try::do_call () at src/libstd/panicking.rs:287
#7  0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#8  0x000055838d93e93d in std::panicking::try () at src/libstd/panicking.rs:265
#9  0x000055838d93e93d in std::panic::catch_unwind () at src/libstd/panic.rs:396
#10 0x000055838d93e93d in std::rt::lang_start_internal () at src/libstd/rt.rs:47
#11 0x000055838d301d82 in main ()

Thread 3 (Thread 0x7f4eaf507700 (LWP 3345327)):
#0  0x00007f4eafcdb41f in __lll_lock_wait () at /usr/lib/libpthread.so.0
#1  0x00007f4eafcd3f31 in pthread_mutex_lock () at /usr/lib/libpthread.so.0
#2  0x00007f4eaf91bc36 in  () at /usr/lib/libgstbase-1.0.so.0
#3  0x00007f4eb0270752 in gst_element_send_event () at /usr/lib/libgstreamer-1.0.so.0
#4  0x000055838d2fb0eb in pokebot::audio_player::AudioPlayer::stop_current ()
#5  0x000055838d2e0330 in pokebot::async_main::{{closure}} ()
#6  0x000055838d2d4a7b in <futures_util::future::unit_error::UnitError<Fut> as core::future::future::Future>::poll ()
#7  0x000055838d2d43f9 in <futures_util::compat::compat03as01::Compat<Fut> as futures::future::Future>::poll ()
#8  0x000055838d8262b2 in futures::task_impl::std::set ()
#9  0x000055838d825f62 in _ZN3std9panicking3try7do_call17h7ea1b09b97765c50E.llvm.12712539897956379439 ()
#10 0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#11 0x000055838d822f79 in tokio_threadpool::task::Task::run ()
#12 0x000055838d82018a in tokio_threadpool::worker::Worker::run_task ()
#13 0x000055838d81f610 in tokio_threadpool::worker::Worker::run ()
#14 0x000055838d8018bc in tokio_reactor::with_default ()
#15 0x000055838d8043af in tokio::runtime::threadpool::builder::Builder::build::{{closure}} ()
#16 0x000055838d8257ea in std::thread::local::LocalKey<T>::with ()
#17 0x000055838d8255d9 in std::thread::local::LocalKey<T>::with ()
#18 0x000055838d81c538 in std::sys_common::backtrace::__rust_begin_short_backtrace ()
#19 0x000055838d825fbc in _ZN3std9panicking3try7do_call17h9939470c3223dedcE.llvm.12712539897956379439 ()
#20 0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#21 0x000055838d81d400 in core::ops::function::FnOnce::call_once{{vtable-shim}} ()
#22 0x000055838d92db6f in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#23 0x000055838d9467a0 in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#24 0x000055838d9467a0 in std::sys_common::thread::start_thread () at src/libstd/sys_common/thread.rs:13
#25 0x000055838d9467a0 in std::sys::unix::thread::Thread::new::thread_start () at src/libstd/sys/unix/thread.rs:79
#26 0x00007f4eafcd14cf in start_thread () at /usr/lib/libpthread.so.0
#27 0x00007f4eafbe62d3 in clone () at /usr/lib/libc.so.6

Thread 4 (Thread 0x7f4eaf306700 (LWP 3345328)):
#0  0x00007f4eafcd7c45 in pthread_cond_wait@@GLIBC_2.3.2 () at /usr/lib/libpthread.so.0
#1  0x000055838d92e983 in std::sys::unix::condvar::Condvar::wait () at src/libstd/sys/unix/condvar.rs:69
#2  0x000055838d92e983 in std::sys_common::condvar::Condvar::wait () at src/libstd/sys_common/condvar.rs:41
#3  0x000055838d92e983 in std::sync::condvar::Condvar::wait () at src/libstd/sync/condvar.rs:204
#4  0x000055838d92e983 in std::thread::park () at src/libstd/thread/mod.rs:908
#5  0x000055838d93a622 in std::sync::mpsc::blocking::WaitToken::wait () at src/libstd/sync/mpsc/blocking.rs:71
#6  0x000055838d40e63f in std::sync::mpsc::sync::Packet<T>::recv ()
#7  0x000055838d48f072 in std::sync::mpsc::Receiver<T>::recv ()
#8  0x000055838d3e0f3b in std::sys_common::backtrace::__rust_begin_short_backtrace ()
#9  0x000055838d427669 in _ZN3std9panicking3try7do_call17h1c8ac8e2f04e5df5E.llvm.18110782884698434161 ()
#10 0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#11 0x000055838d45ce94 in core::ops::function::FnOnce::call_once{{vtable-shim}} ()
#12 0x000055838d92db6f in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#13 0x000055838d9467a0 in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#14 0x000055838d9467a0 in std::sys_common::thread::start_thread () at src/libstd/sys_common/thread.rs:13
#15 0x000055838d9467a0 in std::sys::unix::thread::Thread::new::thread_start () at src/libstd/sys/unix/thread.rs:79
#16 0x00007f4eafcd14cf in start_thread () at /usr/lib/libpthread.so.0
#17 0x00007f4eafbe62d3 in clone () at /usr/lib/libc.so.6

Thread 5 (Thread 0x7f4eaec0f700 (LWP 3345332)):
#0  0x00007f4eafbdbae6 in ppoll () at /usr/lib/libc.so.6
#1  0x00007f4eb02442ce in gst_poll_wait () at /usr/lib/libgstreamer-1.0.so.0
#2  0x00007f4eb027f807 in gst_bus_timed_pop_filtered () at /usr/lib/libgstreamer-1.0.so.0
#3  0x000055838d3de769 in gstreamer::auto::bus::Bus::timed_pop ()
#4  0x000055838d2fb626 in pokebot::audio_player::AudioPlayer::poll ()
#5  0x000055838d30f987 in pokebot::spawn_gstreamer_thread::{{closure}} ()
#6  0x000055838d309636 in std::sys_common::backtrace::__rust_begin_short_backtrace ()
#7  0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#8  0x000055838d30afd6 in core::ops::function::FnOnce::call_once{{vtable-shim}} ()
#9  0x000055838d92db6f in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#10 0x000055838d9467a0 in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#11 0x000055838d9467a0 in std::sys_common::thread::start_thread () at src/libstd/sys_common/thread.rs:13
#12 0x000055838d9467a0 in std::sys::unix::thread::Thread::new::thread_start () at src/libstd/sys/unix/thread.rs:79
#13 0x00007f4eafcd14cf in start_thread () at /usr/lib/libpthread.so.0
#14 0x00007f4eafbe62d3 in clone () at /usr/lib/libc.so.6

Thread 12 (Thread 0x7f4eaf105700 (LWP 3485501)):
#0  0x00007f4eafbe660e in epoll_wait () at /usr/lib/libc.so.6
#1  0x000055838d8ce664 in mio::sys::unix::epoll::Selector::select ()
#2  0x000055838d8cc6f5 in mio::poll::Poll::poll1 ()
#3  0x000055838d8cc283 in mio::poll::Poll::poll ()
#4  0x000055838d80d6a8 in tokio_reactor::Reactor::turn ()
#5  0x000055838d80e271 in <tokio_reactor::Reactor as tokio_executor::park::Park>::park ()
#6  0x000055838d801818 in <tokio_timer::timer::Timer<T,N> as tokio_executor::park::Park>::park ()
#7  0x000055838d804114 in <tokio_threadpool::park::boxed::BoxedPark<T> as tokio_executor::park::Park>::park ()
#8  0x000055838d81fbd9 in tokio_threadpool::worker::Worker::run ()
#9  0x000055838d8018bc in tokio_reactor::with_default ()
#10 0x000055838d8043af in tokio::runtime::threadpool::builder::Builder::build::{{closure}} ()
#11 0x000055838d8257ea in std::thread::local::LocalKey<T>::with ()
#12 0x000055838d8255d9 in std::thread::local::LocalKey<T>::with ()
#13 0x000055838d81c538 in std::sys_common::backtrace::__rust_begin_short_backtrace ()
#14 0x000055838d825fbc in _ZN3std9panicking3try7do_call17h9939470c3223dedcE.llvm.12712539897956379439 ()
#15 0x000055838d9476da in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:78
#16 0x000055838d81d400 in core::ops::function::FnOnce::call_once{{vtable-shim}} ()
#17 0x000055838d92db6f in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#18 0x000055838d9467a0 in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once () at /rustc/73528e339aae0f17a15ffa49a8ac608f50c6cf14/src/liballoc/boxed.rs:942
#19 0x000055838d9467a0 in std::sys_common::thread::start_thread () at src/libstd/sys_common/thread.rs:13
#20 0x000055838d9467a0 in std::sys::unix::thread::Thread::new::thread_start () at src/libstd/sys/unix/thread.rs:79
#21 0x00007f4eafcd14cf in start_thread () at /usr/lib/libpthread.so.0
#22 0x00007f4eafbe62d3 in clone () at /usr/lib/libc.so.6
fkaa commented

Can you reproduce this?

I can now.
If you make sure that tokio only uses one thread stop/skip will never work.

I used this main function to reproduce it:

fn main() {
    log4rs::init_file("log4rs.yml", Default::default()).unwrap();

    let mut rt = tokio::runtime::Builder::new()
        .core_threads(1)
        .build()
        .unwrap();
    rt.block_on(async_main().unit_error().boxed().compat())
        .unwrap();
}

Resolved in #24.