volspotconnect2 crashes

JozoVilcek commented 4 years ago

Sporitfy integration sometimes stops to work on my volumio. I am running Volumio with latest updates and plugin is latest too on Raspberri PI 3

In logs I did find this trace reporting the problem:

Feb 03 22:07:12 volumio volumio[10593]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.42 Android/29 (Mi 9T Pro)"                                                                                                                      [35/1655]
Feb 03 22:07:19 volumio volumio[10593]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SpotifyIdError', src/libcore/result.rs:1084:5
Feb 03 22:07:19 volumio volumio[10593]: stack backtrace:
Feb 03 22:07:20 volumio volumio[10593]: 0:   0x9f3788 - backtrace::backtrace::libunwind::trace::h89fcc71e59e3bc5b
Feb 03 22:07:20 volumio volumio[10593]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/libunwind.rs:88
Feb 03 22:07:20 volumio volumio[10593]: 1:   0x9f3788 - backtrace::backtrace::trace_unsynchronized::h244e30b4d61a86e0
Feb 03 22:07:20 volumio volumio[10593]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/mod.rs:66
Feb 03 22:07:20 volumio volumio[10593]: 2:   0x9f3788 - std::sys_common::backtrace::_print::h978df54e55c6209d
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/sys_common/backtrace.rs:47
Feb 03 22:07:20 volumio volumio[10593]: 3:   0x9f3788 - std::sys_common::backtrace::print::ha75ae47f14b8f7f3
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/sys_common/backtrace.rs:36
Feb 03 22:07:20 volumio volumio[10593]: 4:   0x9f3788 - std::panicking::default_hook::{{closure}}::h004e1d529e652ede
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:200
Feb 03 22:07:20 volumio volumio[10593]: 5:   0x9f3380 - std::panicking::default_hook::h185ef7ff1eea4221
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:214
Feb 03 22:07:20 volumio volumio[10593]: 6:   0x9f3f44 - std::panicking::rust_panic_with_hook::hfe0a86ed15580d4a
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:477
Feb 03 22:07:20 volumio volumio[10593]: 7:   0x9f3b10 - std::panicking::continue_panic_fmt::h182e68ecbb1c932b
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:384
Feb 03 22:07:20 volumio volumio[10593]: 8:   0x9f39fc - rust_begin_unwind
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:311
Feb 03 22:07:20 volumio volumio[10593]: 9:   0xa0a444 - core::panicking::panic_fmt::h7e9f94035af782b3
Feb 03 22:07:20 volumio volumio[10593]: at src/libcore/panicking.rs:85
Feb 03 22:07:20 volumio volumio[10593]: 10:   0xa0a534 - core::result::unwrap_failed::hf7591c1dd9412006
Feb 03 22:07:20 volumio volumio[10593]: at src/libcore/result.rs:1084
Feb 03 22:07:20 volumio volumio[10593]: 11:   0x4a1a44 - librespot_connect::spirc::SpircTask::handle_pause::h714e9c2b482fb525
Feb 03 22:07:20 volumio volumio[10593]: 12:   0x49fc24 - <librespot_connect::spirc::SpircTask as futures::future::Future>::poll::h06898ee98b3380b3
Feb 03 22:07:20 volumio volumio[10593]: 13:   0x474e50 - <vollibrespot::Main as futures::future::Future>::poll::hb49550d8e3f467fa
Feb 03 22:07:20 volumio volumio[10593]: 14:   0x49a9b4 - futures::task_impl::std::set::hb572c3af727256ac
Feb 03 22:07:20 volumio volumio[10593]: 15:   0x472e2c - <futures::future::lazy::Lazy<F,R> as futures::future::Future>::poll::hc872efa618c45de3
Feb 03 22:07:20 volumio volumio[10593]: 16:   0x49a83c - futures::task_impl::std::set::ha1da852080a54e89
Feb 03 22:07:20 volumio volumio[10593]: 17:   0x45f894 - std::thread::local::LocalKey<T>::with::hb33a14aa0d64830e
Feb 03 22:07:20 volumio volumio[10593]: 18:   0x455c1c - tokio_current_thread::Entered<P>::block_on::h6c7f92e99b77886b
Feb 03 22:07:20 volumio volumio[10593]: 19:   0x45f6b4 - std::thread::local::LocalKey<T>::with::h9ec9ec76b26e7edf
Feb 03 22:07:20 volumio volumio[10593]: 20:   0x45f30c - std::thread::local::LocalKey<T>::with::h26f52d592cd722ab
Feb 03 22:07:20 volumio volumio[10593]: 21:   0x45f16c - std::thread::local::LocalKey<T>::with::h22d8fcf69243240c
Feb 03 22:07:20 volumio volumio[10593]: 22:   0x4551e0 - scoped_tls::ScopedKey<T>::set::h3380ded7e37a7882
Feb 03 22:07:20 volumio volumio[10593]: 23:   0x48eee4 - tokio_core::reactor::Core::run::h9c6fa799f1a72320
Feb 03 22:07:20 volumio volumio[10593]: 24:   0x4773ec - vollibrespot::main::h551d8fa54606fabf
Feb 03 22:07:20 volumio volumio[10593]: 25:   0x47e0ac - std::rt::lang_start::{{closure}}::hdc0b123e45936b4e
Feb 03 22:07:20 volumio volumio[10593]: 26:   0x9f3974 - std::rt::lang_start_internal::{{closure}}::h923917fc45a67b03
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/rt.rs:49
Feb 03 22:07:20 volumio volumio[10593]: 27:   0x9f3974 - std::panicking::try::do_call::he118fbfc301d3e1a
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:296
Feb 03 22:07:20 volumio volumio[10593]: 28:   0x9f7e54 - __rust_maybe_catch_panic
Feb 03 22:07:20 volumio volumio[10593]: at src/libpanic_unwind/lib.rs:80
Feb 03 22:07:20 volumio volumio[10593]: 29:   0x9f43c0 - std::panicking::try::hcc03ea850c2702cb
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panicking.rs:275
Feb 03 22:07:20 volumio volumio[10593]: 30:   0x9f43c0 - std::panic::catch_unwind::hf09eaf9043e449c8
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/panic.rs:394
Feb 03 22:07:20 volumio volumio[10593]: 31:   0x9f43c0 - std::rt::lang_start_internal::h87508684140f3dc4
Feb 03 22:07:20 volumio volumio[10593]: at src/libstd/rt.rs:48
Feb 03 22:07:20 volumio volumio[10593]: 32:   0x4783f8 - main
Feb 03 22:07:20 volumio volumio[10593]: 33: 0x76cfc294 - __libc_start_main
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] Sink released
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] Device is inactive!
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] Relinquishing Volumio state, Spotify session: true
Feb 03 22:07:20 volumio volumio[965]: UNSET VOLATILE
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] unSetVolatile called
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] Relinquishing Volumio state to another service, Spotify session: true
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] Received stop
Feb 03 22:07:20 volumio volumio[965]: [SpotifyConnect] FE =>  [ 4, [length]: 1 ]
Feb 03 22:07:20 volumio systemd[1]: volspotconnect2.service: main process exited, code=exited, status=1/FAILURE
Feb 03 22:07:20 volumio systemd[1]: Unit volspotconnect2.service entered failed state.
Feb 03 22:07:20 volumio volumio[10593]: [Vollibrespot] : EventSender disconnected
Feb 03 22:07:20 volumio volumio[10593]: [Vollibrespot] : Exiting Vollibrespot

ashthespy commented 4 years ago

Looks like your trying to play a track that isn't supported - could you share the URI of the track that causes this?

JozoVilcek commented 4 years ago

I do not have an URI at hand right now. I remember I was playing some podcast. Will try to reproduce it again and send more details

ashthespy commented 4 years ago

Podcasts are a bit tricky, Spotify bought a bunch of smaller companies for podcasts, and that has resulted in multiple apis to fetch them. We currently only support the old school ones served from Spotify's servers, and not the external ones..

JozoVilcek commented 4 years ago

I get a bit inconsistent behavior. E.g. I was playing this one: https://open.spotify.com/episode/0fJIZNdSbovdHEcZIliTZb?si=JhCNQIrRQZumIauzG0Vs6g

When I am playing this podcast on phone, I can not send it to volspot. It says it can notplay this.
When playing some song, I can send it to volspot and it starts play song. Then I can issue a play podcast command and it starts playing. However, if I then issue play next / previous track (which is also podcast), volspot crashes and I need to enable / disable plugin to get normal behavior for songs back.

volumio / volumio-plugins

volspotconnect2 crashes #410