I had a machine that was running out of diskspace on /. This does not seem to be handled gracefully. I found an error message in the logs, but then librespot locks up, no longer responds to mdns queries or, I think, server commands.
This was observed with a self-compiled git master version (4e3576b)
Here's the error from the log:
[2019-07-13T02:14:19Z INFO librespot_playback::player] Track "Strobelite (feat. Peven Everett)" loaded
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 28, kind: Other, message: "No space left on device" }', src/libcore/result.r
stack backtrace:
0: 0xa3637c - backtrace::backtrace::libunwind::trace::hb317fd79f338e9ac
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.29/src/backtrace/libunwind.rs:88
1: 0xa3637c - backtrace::backtrace::trace_unsynchronized::h577e08d87958ca80
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.29/src/backtrace/mod.rs:66
2: 0xa3637c - std::sys_common::backtrace::_print::hbfee0f6c5053d54e
at src/libstd/sys_common/backtrace.rs:47
3: 0xa3637c - std::sys_common::backtrace::print::he0aac2b05fe6a451
at src/libstd/sys_common/backtrace.rs:36
4: 0xa3637c - std::panicking::default_hook::{{closure}}::ha2ef00deb6db7a83
at src/libstd/panicking.rs:200
5: 0xa35f2c - std::panicking::default_hook::h641d7e1cec244c78
at src/libstd/panicking.rs:214
6: 0xa36b40 - std::panicking::rust_panic_with_hook::h4043fa8d29430a82
at src/libstd/panicking.rs:477
7: 0xa36704 - std::panicking::continue_panic_fmt::h69e00c7989848347
at src/libstd/panicking.rs:384
8: 0xa365f0 - rust_begin_unwind
at src/libstd/panicking.rs:311
9: 0xa52adc - core::panicking::panic_fmt::h368b1e08709edc0e
at src/libcore/panicking.rs:85
10: 0x6815e0 - core::result::unwrap_failed::hb36bb57d205feb44
11: 0x6df6b8 - librespot_core::cache::Cache::save_file::h4840fbb770c45ce6
12: 0x63728c - <futures::future::map::Map<A,F> as futures::future::Future>::poll::hbf2021502e8fa11b
13: 0x6389cc - futures::future::chain::Chain<A,B,C>::poll::hf56c814a8a30a28e
14: 0x94eb70 - futures::task_impl::std::set::h0f3a1953102917fd
15: 0x95b904 - tokio_current_thread::CurrentRunner::set_spawn::hd28e949e3e27e754
16: 0x955138 - tokio_current_thread::scheduler::Scheduler<U>::tick::h3c9a2fb62e4aa42a
17: 0x95bbf0 - tokio_current_thread::Entered<P>::turn::h54e4b6ec1a6350ff
18: 0x94a1fc - scoped_tls::ScopedKey<T>::set::h027fa554916dcb6c
19: 0x954834 - std::thread::local::LocalKey<T>::with::ha544fc008d9bb431
20: 0x954be8 - std::thread::local::LocalKey<T>::with::hec21127b56529e20
21: 0x954398 - std::thread::local::LocalKey<T>::with::h654d467430281288
22: 0x953c38 - tokio_core::reactor::Core::poll::hfd8ca804eabf02a7
23: 0x53dc48 - tokio_core::reactor::Core::run::ha8a4a8d15df4a05f
24: 0x54bb44 - librespot::main::h17b86eb414fa277e
25: 0x5263dc - std::rt::lang_start::{{closure}}::he764af215f6d223f
26: 0xa36568 - std::rt::lang_start_internal::{{closure}}::hfac715f2e0a14136
at src/libstd/rt.rs:49
27: 0xa36568 - std::panicking::try::do_call::h5bd3d572724ac2e1
at src/libstd/panicking.rs:296
28: 0xa3db18 - __rust_maybe_catch_panic
at src/libpanic_unwind/lib.rs:82
29: 0xa36fd0 - std::panicking::try::h3203ccbd3c7c13af
at src/libstd/panicking.rs:275
30: 0xa36fd0 - std::panic::catch_unwind::hd9cff17009151b9a
So it seems there is some kind of lockup.
It seems librespot has stopped reading from the mdns socket:
pi@DiningRoom:~ $ sudo netstat -lnp4|grep librespot
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:36127 0.0.0.0:* LISTEN 4233/librespot
udp 142144 0 0.0.0.0:5353 0.0.0.0:* 4233/librespot
gdb suggests that all threads are locked up:
[New LWP 4237]
[New LWP 5707]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
0x76c33464 in pthread_join (threadid=, thread_return=0x0) at pthread_join.c:90
90 pthread_join.c: No such file or directory.
(gdb)
(gdb) bt
#0 0x76c33464 in pthread_join (threadid=, thread_return=0x0) at pthread_join.c:90
#1 0x00a3d030 in std::sys::unix::thread::Thread::join::h98dd53d2904cc322 () at src/libstd/sys/unix/thread.rs:165
#2 0x005da538 in std::thread::JoinHandle$LT$T$GT$::join::h0853f4a1e7365593 ()
#3 0x005d5ac0 in _$LT$librespot_playback..player..Player$u20$as$u20$core..ops..drop..Drop$GT$::drop::h8b117a771a89b4b4 ()
#4 0x0053e78c in core::ptr::real_drop_in_place::h1186091d46e6fc50 ()
#5 0x0054e2b4 in core::ptr::real_drop_in_place::h81963297eb6d1e60 ()
#6 0x0054fa88 in _$LT$tokio_current_thread..scheduler..Scheduler$LT$U$GT$$u20$as$u20$core..ops..drop..Drop$GT$::drop::h58f9143f85f1f7fd ()
#7 0x00546c4c in core::ptr::real_drop_in_place::hc143416570f48b51 ()
#8 0x00544938 in core::ptr::real_drop_in_place::h32239ca035a0d27e ()
#9 0x0054c87c in librespot::main::h17b86eb414fa277e ()
#10 0x7e6ca000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 2
[Switching to thread 2 (Thread 0x76b7e120 (LWP 4237))]
#0 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
#1 0x00999e98 in mio::sys::unix::epoll::Selector::select::h0a54d4dfa45e8290 ()
#2 0x00995c1c in mio::poll::Poll::poll1::hd301b86e747a2f5c ()
#3 0x0099573c in mio::poll::Poll::poll::h4fcbf39efec82893 ()
#4 0x0096f090 in tokio_reactor::Reactor::turn::h20570c2a4f4cd7f5 ()
#5 0x00976370 in tokio_reactor::background::run::hb60424d1fa1ebe61 ()
#6 0x009773d4 in std::sys_common::backtrace::__rust_begin_short_backtrace::hd90d34c7b227e928 ()
#7 0x0097742c in std::panicking::try::do_call::h311e790d422b1035 ()
#8 0x00a3db18 in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:82
#9 0x00972acc in core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h752fe7814e947266 ()
#10 0x00a275ec in _$LT$alloc..boxed..Box$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$A$GT$$GT$::call_once::h7221d3aa987d9f9f ()
at /rustc/cd2cd4c9627e52c33e68e8c93a8916dc11094cbb/src/liballoc/boxed.rs:766
#11 0x00a3cf58 in _$LT$alloc..boxed..Box$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$A$GT$$GT$::call_once::hac0611ced21f0fdb ()
at /rustc/cd2cd4c9627e52c33e68e8c93a8916dc11094cbb/src/liballoc/boxed.rs:766
#12 std::sys_common::thread::start_thread::h0b76a8eba260b4de () at src/libstd/sys_common/thread.rs:13
#13 std::sys::unix::thread::Thread::new::thread_start::h00b237f6f0bbec97 () at src/libstd/sys/unix/thread.rs:79
#14 0x76c31fc4 in start_thread (arg=0x76b7e120) at pthread_create.c:458
#15 0x76e3d038 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:76 from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 3
[Switching to thread 3 (Thread 0x757fe120 (LWP 5707))]
#0 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
188 pthread_cond_wait.c: No such file or directory.
(gdb) bt
#0 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
#1 0x00636620 in _$LT$librespot_audio..fetch..AudioFileStreaming$u20$as$u20$std..io..Read$GT$::read::h35f2b025181efe57 ()
#2 0x00636950 in _$LT$librespot_audio..fetch..AudioFile$u20$as$u20$std..io..Read$GT$::read::h29fbd4695955c27b ()
#3 0x005fee80 in ogg::reading::UntilPageHeaderReader::do_read::hc87bdd9d28e10f3e ()
#4 0x005fe5bc in ogg::reading::PacketReader$LT$T$GT$::read_ogg_page::h2551059ca789be2a ()
#5 0x005fdb14 in ogg::reading::PacketReader$LT$T$GT$::seek_absgp::he106f00f34297b4e ()
#6 0x005f3798 in lewton::inside_ogg::OggStreamReader$LT$T$GT$::seek_absgp_pg::h918ebdaa8e2ea5cd ()
#7 0x005d7b6c in librespot_playback::player::PlayerInternal::run::h19c92446937f2f52 ()
#8 0x757fcb50 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) info threads
Id Target Id Frame
- 1 Thread 0x76efd000 (LWP 4233) "librespot" 0x76c33464 in pthread_join (threadid=, thread_return=0x0) at pthread_join.c:90
2 Thread 0x76b7e120 (LWP 4237) "librespot" 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
3 Thread 0x757fe120 (LWP 5707) "librespot" 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
Letting it run for a minute and breaking again, shows identical stacktraces,
Strace shows no syscalls, apart from a pending futex (IIUC):
strace: Process 4233 attached
futex(0x757fe188, FUTEX_WAIT, 5707, NULLstrace: Process 4233 detached
<detached ...>
I made a core dump file. If it helps, I can share it (but I'm a bit hesitant, since I'm not sure if there's sensitive credentials in there).
Not sure if this is really something that is worth fixing, but I gathered all this debug info before looking at the log and discovering that the cause was out-of-space, and I wanted to share my findings anyway.
I had a machine that was running out of diskspace on
/. This does not seem to be handled gracefully. I found an error message in the logs, but then librespot locks up, no longer responds to mdns queries or, I think, server commands.This was observed with a self-compiled git master version (4e3576b)
Here's the error from the log:
So it seems there is some kind of lockup.
It seems librespot has stopped reading from the mdns socket:
pi@DiningRoom:~ $ sudo netstat -lnp4|grep librespot
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:36127 0.0.0.0:* LISTEN 4233/librespot
udp 142144 0 0.0.0.0:5353 0.0.0.0:* 4233/librespot
gdb suggests that all threads are locked up:
[New LWP 4237]
[New LWP 5707]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
0x76c33464 in pthread_join (threadid=, thread_return=0x0) at pthread_join.c:90
90 pthread_join.c: No such file or directory.
(gdb)
(gdb) bt
#0 0x76c33464 in pthread_join (threadid=, thread_return=0x0) at pthread_join.c:90
#1 0x00a3d030 in std::sys::unix::thread::Thread::join::h98dd53d2904cc322 () at src/libstd/sys/unix/thread.rs:165
#2 0x005da538 in std::thread::JoinHandle$LT$T$GT$::join::h0853f4a1e7365593 ()
#3 0x005d5ac0 in _$LT$librespot_playback..player..Player$u20$as$u20$core..ops..drop..Drop$GT$::drop::h8b117a771a89b4b4 ()
#4 0x0053e78c in core::ptr::real_drop_in_place::h1186091d46e6fc50 ()
#5 0x0054e2b4 in core::ptr::real_drop_in_place::h81963297eb6d1e60 ()
#6 0x0054fa88 in _$LT$tokio_current_thread..scheduler..Scheduler$LT$U$GT$$u20$as$u20$core..ops..drop..Drop$GT$::drop::h58f9143f85f1f7fd ()
#7 0x00546c4c in core::ptr::real_drop_in_place::hc143416570f48b51 ()
#8 0x00544938 in core::ptr::real_drop_in_place::h32239ca035a0d27e ()
#9 0x0054c87c in librespot::main::h17b86eb414fa277e ()
#10 0x7e6ca000 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 2
[Switching to thread 2 (Thread 0x76b7e120 (LWP 4237))]
#0 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
#1 0x00999e98 in mio::sys::unix::epoll::Selector::select::h0a54d4dfa45e8290 ()
#2 0x00995c1c in mio::poll::Poll::poll1::hd301b86e747a2f5c ()
#3 0x0099573c in mio::poll::Poll::poll::h4fcbf39efec82893 ()
#4 0x0096f090 in tokio_reactor::Reactor::turn::h20570c2a4f4cd7f5 ()
#5 0x00976370 in tokio_reactor::background::run::hb60424d1fa1ebe61 ()
#6 0x009773d4 in std::sys_common::backtrace::__rust_begin_short_backtrace::hd90d34c7b227e928 ()
#7 0x0097742c in std::panicking::try::do_call::h311e790d422b1035 ()
#8 0x00a3db18 in __rust_maybe_catch_panic () at src/libpanic_unwind/lib.rs:82
#9 0x00972acc in core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h752fe7814e947266 ()
#10 0x00a275ec in _$LT$alloc..boxed..Box$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$A$GT$$GT$::call_once::h7221d3aa987d9f9f ()
at /rustc/cd2cd4c9627e52c33e68e8c93a8916dc11094cbb/src/liballoc/boxed.rs:766
#11 0x00a3cf58 in _$LT$alloc..boxed..Box$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$A$GT$$GT$::call_once::hac0611ced21f0fdb ()
at /rustc/cd2cd4c9627e52c33e68e8c93a8916dc11094cbb/src/liballoc/boxed.rs:766
#12 std::sys_common::thread::start_thread::h0b76a8eba260b4de () at src/libstd/sys_common/thread.rs:13
#13 std::sys::unix::thread::Thread::new::thread_start::h00b237f6f0bbec97 () at src/libstd/sys/unix/thread.rs:79
#14 0x76c31fc4 in start_thread (arg=0x76b7e120) at pthread_create.c:458
#15 0x76e3d038 in ?? () at ../sysdeps/unix/sysv/linux/arm/clone.S:76 from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 3
[Switching to thread 3 (Thread 0x757fe120 (LWP 5707))]
#0 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
188 pthread_cond_wait.c: No such file or directory.
(gdb) bt
#0 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
#1 0x00636620 in _$LT$librespot_audio..fetch..AudioFileStreaming$u20$as$u20$std..io..Read$GT$::read::h35f2b025181efe57 ()
#2 0x00636950 in _$LT$librespot_audio..fetch..AudioFile$u20$as$u20$std..io..Read$GT$::read::h29fbd4695955c27b ()
#3 0x005fee80 in ogg::reading::UntilPageHeaderReader::do_read::hc87bdd9d28e10f3e ()
#4 0x005fe5bc in ogg::reading::PacketReader$LT$T$GT$::read_ogg_page::h2551059ca789be2a ()
#5 0x005fdb14 in ogg::reading::PacketReader$LT$T$GT$::seek_absgp::he106f00f34297b4e ()
#6 0x005f3798 in lewton::inside_ogg::OggStreamReader$LT$T$GT$::seek_absgp_pg::h918ebdaa8e2ea5cd ()
#7 0x005d7b6c in librespot_playback::player::PlayerInternal::run::h19c92446937f2f52 ()
#8 0x757fcb50 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) info threads
Id Target Id Frame
2 Thread 0x76b7e120 (LWP 4237) "librespot" 0x76e3d704 in epoll_wait () at ../sysdeps/unix/syscall-template.S:84
3 Thread 0x757fe120 (LWP 5707) "librespot" 0x76c389a4 in __pthread_cond_wait (cond=0x75901140, mutex=0x75900730) at pthread_cond_wait.c:188
Letting it run for a minute and breaking again, shows identical stacktraces,
Strace shows no syscalls, apart from a pending futex (IIUC):
strace: Process 4233 attached
futex(0x757fe188, FUTEX_WAIT, 5707, NULLstrace: Process 4233 detached
<detached ...>
I made a core dump file. If it helps, I can share it (but I'm a bit hesitant, since I'm not sure if there's sensitive credentials in there).
Not sure if this is really something that is worth fixing, but I gathered all this debug info before looking at the log and discovering that the cause was out-of-space, and I wanted to share my findings anyway.