Thank you for your donation!


Problem: librespot crash after DAC power off
#1
Hi,

i'm using rasbperry 4 running moode 7.1 connected via USB cable Cambridge audio CXA81 amplifier with build in DAC.
Everything works very well with one exception, when I'm powering off amplifier while playing music from spotify, librespot crashes

In order to debug it, I've started proces in verbose mode running following command
Code:
sudo librespot --name CambridgeAudio --bitrate 320 --initial-volume 100 --volume-ctrl linear --autoplay --cache /var/local/www/spotify_cache --disable-audio-cache --backend alsa --device alsaequal --verbose  --onevent /var/local/www/commandw/spotevent.sh

when I start playing music and power off amplifier, following error log appear in the console


Code:
ALSA lib pcm.c:8424:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:8427:(snd_pcm_recover) cannot recovery from underrun, prepare failed: File descriptor in bad state
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: Error("snd_pcm_recover", Sys(EBADFD))', playback/src/audio_backend/alsa.rs:142:61
stack backtrace:
  0:   0x8c6e00 - std::backtrace_rs::backtrace::libunwind::trace::h03f08998830b327f
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
  1:   0x8c6e00 - std::backtrace_rs::backtrace::trace_unsynchronized::hc904ce59e3b3ddf8
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
  2:   0x8c6e00 - std::sys_common::backtrace::_print_fmt::hc6ca3e88c9c15384
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:67:5
  3:   0x8c6e00 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h96b70ae78df0c6ff
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:46:22
  4:   0x8f142c - core::fmt::write::hd1e952447dcf60ff
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/fmt/mod.rs:1078:17
  5:   0x8be990 - std::io::Write::write_fmt::h9c9e73249660260e
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/io/mod.rs:1517:15
  6:   0x8c9628 - std::sys_common::backtrace::_print::h48c27a23da6d8107
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:49:5
  7:   0x8c9628 - std::sys_common::backtrace::print::hcb4061a9ac940b04
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:36:9
  8:   0x8c9628 - std::panicking::default_hook::{{closure}}::h68ceed982cb697a5
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:208:50
  9:   0x8c9054 - std::panicking::default_hook::h90748cf9ce43cfc9
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:225:9
 10:   0x8c9e3c - std::panicking::rust_panic_with_hook::hbddc3a086ec95248
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:591:17
 11:   0x8c999c - std::panicking::begin_panic_handler::{{closure}}::h83ccc4302bb49358
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:497:13
 12:   0x8c737c - std::sys_common::backtrace::__rust_end_short_backtrace::h3142e1e09cb0c983
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:141:18
 13:   0x8c98e4 - rust_begin_unwind
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:493:5
 14:   0x8ede5c - core::panicking::panic_fmt::he396093a5f6f49ce
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/panicking.rs:92:14
 15:   0x8edcb4 - core::option::expect_none_failed::h63bf2dccfc18387b
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/option.rs:1268:5
 16:   0x5c2ec4 - <librespot_playback::audio_backend::alsa::AlsaSink as librespot_playback::audio_backend::Sink>::write::h0b69d1ceededa1cd
 17:   0x5cef70 - <librespot_playback::player::PlayerInternal as futures::future::Future>::poll::h79a44c57fca0690c
 18:   0x518750 - std::sys_common::backtrace::__rust_begin_short_backtrace::hab0b5ae799b3819b
 19:   0x519950 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hab1cf2ea4398dc70
 20:   0x8d04e0 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h39ca8f5e1255e35d
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/alloc/src/boxed.rs:1328:9
 21:   0x8d04e0 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h032a878b93a7e697
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/alloc/src/boxed.rs:1328:9
 22:   0x8d04e0 - std::sys::unix::thread::Thread::new::thread_start::he7a0e9f89a4fa658
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys/unix/thread.rs:71:17
[2021-03-26T19:39:39Z DEBUG librespot_playback::player] drop PlayerInternal[0]
[2021-03-26T19:41:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:43:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:45:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:47:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:49:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:51:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
[2021-03-26T19:53:20Z DEBUG librespot_core::session] Session[0] strong=2 weak=4
 
but process still works until I will disconnect spotify on my computer/mobile, once I change output to local machine following log appear in the console
Code:
[2021-03-26T19:54:28Z DEBUG librespot_connect::spirc] kMessageTypeNotify "MacBook Pro" f0d5f004f8f7bfb770802c26de3ddfd012edde44 1880765975 1616788468519 kPlayStatusStop
[2021-03-26T19:54:29Z DEBUG librespot_connect::spirc] kMessageTypeNotify "MacBook Pro" f0d5f004f8f7bfb770802c26de3ddfd012edde44 1880767268 1616788469812 kPlayStatusPlay
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', playback/src/player.rs:277:61
stack backtrace:
  0:   0x8c6e00 - std::backtrace_rs::backtrace::libunwind::trace::h03f08998830b327f
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
  1:   0x8c6e00 - std::backtrace_rs::backtrace::trace_unsynchronized::hc904ce59e3b3ddf8
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
  2:   0x8c6e00 - std::sys_common::backtrace::_print_fmt::hc6ca3e88c9c15384
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:67:5
  3:   0x8c6e00 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h96b70ae78df0c6ff
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:46:22
  4:   0x8f142c - core::fmt::write::hd1e952447dcf60ff
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/fmt/mod.rs:1078:17
  5:   0x8be990 - std::io::Write::write_fmt::h9c9e73249660260e
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/io/mod.rs:1517:15
  6:   0x8c9628 - std::sys_common::backtrace::_print::h48c27a23da6d8107
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:49:5
  7:   0x8c9628 - std::sys_common::backtrace::print::hcb4061a9ac940b04
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:36:9
  8:   0x8c9628 - std::panicking::default_hook::{{closure}}::h68ceed982cb697a5
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:208:50
  9:   0x8c9054 - std::panicking::default_hook::h90748cf9ce43cfc9
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:225:9
 10:   0x8c9e3c - std::panicking::rust_panic_with_hook::hbddc3a086ec95248
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:591:17
 11:   0x8c999c - std::panicking::begin_panic_handler::{{closure}}::h83ccc4302bb49358
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:497:13
 12:   0x8c737c - std::sys_common::backtrace::__rust_end_short_backtrace::h3142e1e09cb0c983
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/sys_common/backtrace.rs:141:18
 13:   0x8c98e4 - rust_begin_unwind
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:493:5
 14:   0x8ede5c - core::panicking::panic_fmt::he396093a5f6f49ce
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/panicking.rs:92:14
 15:   0x8edcb4 - core::option::expect_none_failed::h63bf2dccfc18387b
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/option.rs:1268:5
 16:   0x5c77b8 - librespot_playback::player::Player::command::h6247f2019150bef4
 17:   0x5c791c - librespot_playback::player::Player::stop::hd8b17c78a3f01aaa
 18:   0x59bf28 - <librespot_connect::spirc::SpircTask as futures::future::Future>::poll::hbfbb6ab224368cff
 19:   0x539e28 - <librespot::Main as futures::future::Future>::poll::h496b11a2e55c6fcf
 20:   0x52f934 - futures::task_impl::Spawn<T>::enter::{{closure}}::hfa91044fa2763699
 21:   0x53cec0 - librespot::main::h9ca5fc77fed0670f
 22:   0x518198 - std::sys_common::backtrace::__rust_begin_short_backtrace::h999d5981e7f994c3
 23:   0x518fbc - std::rt::lang_start::{{closure}}::h6cb924fff4c08117
 24:   0x8ca25c - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h221669f198ddd75e
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/core/src/ops/function.rs:259:13
 25:   0x8ca25c - std::panicking::try::do_call::h2f523e82afd7b171
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:379:40
 26:   0x8ca25c - std::panicking::try::h23f86446f10cedcb
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panicking.rs:343:19
 27:   0x8ca25c - std::panic::catch_unwind::hd9d2d31af6b8e2f8
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/panic.rs:396:14
 28:   0x8ca25c - std::rt::lang_start_internal::h2070b43e8853ebbe
                      at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b/library/std/src/rt.rs:51:25
 29:   0x53ed00 - main
 30: 0xb6c3d718 - __libc_start_main
[2021-03-26T19:54:29Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2021-03-26T19:54:29Z DEBUG librespot_playback::player] Shutting down player thread ...
[2021-03-26T19:54:29Z ERROR librespot_playback::player] Player thread panicked!
[2021-03-26T19:54:29Z DEBUG librespot_core::session] drop Session[0]
[2021-03-26T19:54:29Z DEBUG librespot_core::audio_key] drop AudioKeyManager
[2021-03-26T19:54:29Z DEBUG librespot_core::channel] drop ChannelManager
[2021-03-26T19:54:29Z DEBUG librespot_core::mercury] drop MercuryManager
[2021-03-26T19:54:29Z DEBUG librespot_core::session] drop Dispatch

How i can fix this issue? I was thinking about detecting that librespot process is down and restarting it but it doesn't die until i disconnect so it would be still semi automatic solution.

any ideas?

Many thanks for help
Reply


Forum Jump: