Hi everyone,
I’m running Volumio v2.703 with Spotify plugin v2.0.2 and Spotify connect2 plugin v0.9.9.
Spotify connect stopped working (it was working when I installed the system).
I’m not able to see Volumio from Spotify app on my other devices (e.g. my phone) and so I’m not able to remotely control Spotify on Volumio.
Spotify browsing and playback is working via Volumio interface (also if volume control seems to not have any effect).
I tried uninstalling and then installing again Spotify plugins without any success.
I enabled also the debug mode for Spotify connect2 plugin but I don’t know if there is any log file to check and eventually troubleshoot.
Do you have any suggestion to fix the issue?
Thanks!
1 Like
Have you tried to disable and reanble the plugin?
Log appears in console. You need to activate SSH.
See the doc
Yes, I tried to disable and re-enable the plugin but I didn’t solve the issue.
As I wrote before I also tried to uninstall and then install again all Spotify plugins.
I will look at the logs in order to see if there is any message that can help me to find a fix.
I noticed that most probably there is a mismatch between the plugin version I installed and the last one available on github.
Eventually I will try to manually re-install the plugin.
I will keep you posted if I have any news.
Thanks.
Don’t need to install from github. Use the official version.
There is no link between plugins Spotify connect and Spotify
There is no need to remove and reinstall plugin. You are not on windows…
Try to connect, if you can, with an other device (smartphone, pc). A recent update from Spotify caused some problems…
Hello,
this is the error I get every time I try to use Spotify connect on Volumio from any of my other device.
2020-02-24T13:37:10.453Z - info: New Spotify access token = XXX
2020-02-24T13:37:10.460Z - info: Spotify credentials grant success - running version from March 24, 2019
2020-02-24T13:37:11.037Z - info: An error occurred while listing Spotify categories WebapiError: Unauthorized
2020-02-24T13:37:11.221Z - info: Fetching Streaming Services browse cache
2020-02-24T13:37:11.520Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ
2020-02-24T13:37:11.530Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
2020-02-24T13:37:11.642Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesTIDAL
2020-02-24T13:37:11.645Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
2020-02-24T13:37:13.091Z - info: An error occurred while listing Spotify featured playlists WebapiError: Unauthorized
2020-02-24T13:37:14.016Z - info: An error occurred while listing Spotify new albums WebapiError: Unauthorized
2020-02-24T13:47:18.585Z - info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false}
I’ve just hidden the token code.
After this error Volumio disappears from the available devices on Spotify.
Disabling/enabling the Spotify connect plugin makes Volumio appear again.
Any idea about what can I do to fix this?
You seem to be mixing up both the Spotfy and the Spotify Connect plugins.
The Spotify plugin lets you search for and play music directly from the Volumio interface.
The Spotify Connect (volspotconnect2) plugin lets you use the native Spotiyfy app on your desktop/phone/tablet and connect to the device.
For volspotconnect2 specific logs, try running
sudo journalctl -u volspotconnect2.serviceYou are right, I’m going to provide the proper log ASAP.
This is what I get trying to connect from my phone:
Feb 25 11:20:00 volumio volumio[4524]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:00 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:20:00 volumio volumio[4524]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:00 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:20:06 volumio volumio[4524]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:06 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:20:07 volumio volumio[4524]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:07 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:20:08 volumio volumio[4524]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:09 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:20:09 volumio volumio[4524]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:20:09 volumio volumio[4524]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-928c.ap.spotify.com:4070"
Feb 25 11:20:10 volumio volumio[4524]: [Vollibrespot] : Authenticated as "neoben.86" !
Feb 25 11:20:10 volumio volumio[4524]: [Vollibrespot] librespot_core::session: new Session[0]
Feb 25 11:20:10 volumio volumio[4524]: [Vollibrespot] : Setting up new mixer: card:hw:0 mixer:Digital index:0
Feb 25 11:20:10 volumio volumio[4524]: thread 'main' panicked at 'Couldn't find SelemId', src/libcore/option.rs:1166:5
Feb 25 11:20:10 volumio volumio[4524]: stack backtrace:
Feb 25 11:20:10 volumio volumio[4524]: 0: 0xa08df8 - backtrace::backtrace::libunwind::trace::h89fcc71e59e3bc5b
Feb 25 11:20:10 volumio volumio[4524]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/libunwind.rs:88
Feb 25 11:20:10 volumio volumio[4524]: 1: 0xa08df8 - backtrace::backtrace::trace_unsynchronized::h244e30b4d61a86e0
Feb 25 11:20:10 volumio volumio[4524]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/mod.rs:66
Feb 25 11:20:10 volumio volumio[4524]: 2: 0xa08df8 - std::sys_common::backtrace::_print::h978df54e55c6209d
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/sys_common/backtrace.rs:47
Feb 25 11:20:10 volumio volumio[4524]: 3: 0xa08df8 - std::sys_common::backtrace::print::ha75ae47f14b8f7f3
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/sys_common/backtrace.rs:36
Feb 25 11:20:10 volumio volumio[4524]: 4: 0xa08df8 - std::panicking::default_hook::{{closure}}::h004e1d529e652ede
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/panicking.rs:200
Feb 25 11:20:10 volumio volumio[4524]: 5: 0xa089dc - std::panicking::default_hook::h185ef7ff1eea4221
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/panicking.rs:214
Feb 25 11:20:10 volumio volumio[4524]: 6: 0xa095b4 - std::panicking::rust_panic_with_hook::hfe0a86ed15580d4a
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/panicking.rs:477
Feb 25 11:20:10 volumio volumio[4524]: 7: 0xa09180 - std::panicking::continue_panic_fmt::h182e68ecbb1c932b
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/panicking.rs:384
Feb 25 11:20:10 volumio volumio[4524]: 8: 0xa0906c - rust_begin_unwind
Feb 25 11:20:10 volumio volumio[4524]: at src/libstd/panicking.rs:311
Feb 25 11:20:11 volumio volumio[4524]: 9: 0xa2240c - core::panicking::panic_fmt::h7e9f94035af782b3
Feb 25 11:20:11 volumio volumio[4524]: at src/libcore/panicking.rs:85
Feb 25 11:20:11 volumio volumio[4524]: 10: 0xa22478 - core::option::expect_failed::h292a6217b603c24f
Feb 25 11:20:11 volumio volumio[4524]: at src/libcore/option.rs:1166
Feb 25 11:20:11 volumio volumio[4524]: 11: 0x53f8e0 - <librespot_playback::mixer::alsamixer::AlsaMixer as librespot_playback::mixer::Mixer>::open::hb29b91d9a2daf069
Feb 25 11:20:11 volumio volumio[4524]: 12: 0x46b430 - librespot_playback::mixer::mk_sink::h6af7200b33ccd82d
Feb 25 11:20:11 volumio volumio[4524]: 13: 0x475208 - <vollibrespot::Main as futures::future::Future>::poll::hb49550d8e3f467fa
Feb 25 11:20:11 volumio volumio[4524]: 14: 0x49c4e4 - futures::task_impl::std::set::hb572c3af727256ac
Feb 25 11:20:11 volumio volumio[4524]: 15: 0x4736e8 - <futures::future::lazy::Lazy<F,R> as futures::future::Future>::poll::hc872efa618c45de3
Feb 25 11:20:11 volumio volumio[4524]: 16: 0x49c368 - futures::task_impl::std::set::ha1da852080a54e89
Feb 25 11:20:11 volumio volumio[4524]: 17: 0x45fa80 - std::thread::local::LocalKey<T>::with::hb33a14aa0d64830e
Feb 25 11:20:11 volumio volumio[4524]: 18: 0x4557a0 - tokio_current_thread::Entered<P>::block_on::h6c7f92e99b77886b
Feb 25 11:20:11 volumio volumio[4524]: 19: 0x45f898 - std::thread::local::LocalKey<T>::with::h9ec9ec76b26e7edf
Feb 25 11:20:11 volumio volumio[4524]: 20: 0x45f500 - std::thread::local::LocalKey<T>::with::h26f52d592cd722ab
Feb 25 11:20:11 volumio volumio[4524]: 21: 0x45f358 - std::thread::local::LocalKey<T>::with::h22d8fcf69243240c
Feb 25 11:20:11 volumio volumio[4524]: 22: 0x454d70 - scoped_tls::ScopedKey<T>::set::h3380ded7e37a7882
Feb 25 11:20:11 volumio systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a
Feb 25 11:20:11 volumio systemd[1]: Unit volspotconnect2.service entered failed state.
Feb 25 11:20:11 volumio volumio[4524]: 23: 0x4903dc - tokio_core::reactor::Core::run::h9c6fa799f1a72320
Feb 25 11:20:11 volumio volumio[4524]: 24: 0x477cd4 - vollibrespot::main::h551d8fa54606fabf
Feb 25 11:20:11 volumio volumio[4524]: 25: 0x47eb84 - std::rt::lang_start::{{closure}}::hdc0b123e45936b4e
Feb 25 11:20:11 volumio volumio[4524]: 26: 0xa08fe4 - std::rt::lang_start_internal::{{closure}}::h923917fc45a67b03
Feb 25 11:20:11 volumio volumio[4524]: at src/libstd/rt.rs:49
Feb 25 11:20:11 volumio volumio[4524]: 27: 0xa08fe4 - std::panicking::try::do_call::he118fbfc301d3e1a
Feb 25 11:20:11 volumio volumio[4524]: at src/libstd/panicking.rs:296
Feb 25 11:20:11 volumio volumio[4524]: 28: 0xa0d59c - __rust_maybe_catch_panic
Feb 25 11:20:11 volumio volumio[4524]: at src/libpanic_unwind/lib.rs:80
Feb 25 11:20:11 volumio volumio[4524]: 29: 0xa09a44 - std::panicking::try::hcc03ea850c2702cb
Feb 25 11:20:11 volumio volumio[4524]: at src/libstd/panicking.rs:275
Feb 25 11:20:11 volumio volumio[4524]: 30: 0xa09a44 - std::panic::catch_unwind::hf09eaf9043e449c8
Feb 25 11:20:11 volumio volumio[4524]: at src/libstd/panic.rs:394
Feb 25 11:20:11 volumio volumio[4524]: 31: 0xa09a44 - std::rt::lang_start_internal::h87508684140f3dc4
Feb 25 11:20:11 volumio volumio[4524]: at src/libstd/rt.rs:48
Feb 25 11:20:11 volumio volumio[4524]: 32: 0x478cd8 - main
Feb 25 11:20:11 volumio volumio[4524]: 33: 0xb6cca294 - __libc_start_main
Feb 25 11:20:11 volumio volumio[4524]: [Vollibrespot] librespot_core::session: drop Session[0]
Feb 25 11:20:11 volumio volumio[4524]: [Vollibrespot] librespot_core::session: drop Dispatch
Feb 25 11:20:13 volumio systemd[1]: volspotconnect2.service holdoff time over, scheduling restart.
Feb 25 11:20:13 volumio systemd[1]: Stopping Volspotconnect2 Daemon...
Feb 25 11:20:13 volumio systemd[1]: Starting Volspotconnect2 Daemon...
Feb 25 11:20:13 volumio systemd[1]: Started Volspotconnect2 Daemon.
Feb 25 11:20:13 volumio volumio[384]: vollibrespot v0.1.9 c98fd5d 2019-11-08 (librespot 4674946 2019-11-08) -- Built On 2019-11-08
Feb 25 11:20:13 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:37501
Feb 25 11:20:13 volumio volumio[384]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
Feb 25 11:20:31 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:20:31 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:20:31 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:20:31 volumio volumio[384]: [Vollibrespot] : Login error for user "neoben.86": MAC mismatch
Feb 25 11:26:23 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:26:23 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:26:23 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:26:23 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:26:30 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/8.5.46 Android/28 (Mi A1)"
Feb 25 11:26:30 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
This is what I get trying to connect from my laptop (pretty much it’s the same issue):
Feb 25 11:35:49 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:35:49 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:35:51 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:35:51 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:35:53 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:35:53 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:35:55 volumio volumio[384]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:35:55 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:35:55 volumio volumio[384]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:35:56 volumio volumio[384]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-t1zs.ap.spotify.com:4070"
Feb 25 11:35:56 volumio volumio[384]: [Vollibrespot] : Authenticated as "neoben.86" !
Feb 25 11:35:56 volumio volumio[384]: [Vollibrespot] librespot_core::session: new Session[0]
Feb 25 11:35:56 volumio volumio[384]: [Vollibrespot] : Setting up new mixer: card:hw:0 mixer:Digital index:0
Feb 25 11:35:56 volumio volumio[384]: thread 'main' panicked at 'Couldn't find SelemId', src/libcore/option.rs:1166:5
Feb 25 11:35:56 volumio volumio[384]: stack backtrace:
Feb 25 11:35:57 volumio volumio[384]: 0: 0xa44df8 - backtrace::backtrace::libunwind::trace::h89fcc71e59e3bc5b
Feb 25 11:35:57 volumio volumio[384]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/libunwind.rs:88
Feb 25 11:35:57 volumio volumio[384]: 1: 0xa44df8 - backtrace::backtrace::trace_unsynchronized::h244e30b4d61a86e0
Feb 25 11:35:57 volumio volumio[384]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/mod.rs:66
Feb 25 11:35:57 volumio volumio[384]: 2: 0xa44df8 - std::sys_common::backtrace::_print::h978df54e55c6209d
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/sys_common/backtrace.rs:47
Feb 25 11:35:57 volumio volumio[384]: 3: 0xa44df8 - std::sys_common::backtrace::print::ha75ae47f14b8f7f3
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/sys_common/backtrace.rs:36
Feb 25 11:35:57 volumio volumio[384]: 4: 0xa44df8 - std::panicking::default_hook::{{closure}}::h004e1d529e652ede
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:200
Feb 25 11:35:57 volumio volumio[384]: 5: 0xa449dc - std::panicking::default_hook::h185ef7ff1eea4221
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:214
Feb 25 11:35:57 volumio volumio[384]: 6: 0xa455b4 - std::panicking::rust_panic_with_hook::hfe0a86ed15580d4a
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:477
Feb 25 11:35:57 volumio volumio[384]: 7: 0xa45180 - std::panicking::continue_panic_fmt::h182e68ecbb1c932b
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:384
Feb 25 11:35:57 volumio volumio[384]: 8: 0xa4506c - rust_begin_unwind
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:311
Feb 25 11:35:57 volumio volumio[384]: 9: 0xa5e40c - core::panicking::panic_fmt::h7e9f94035af782b3
Feb 25 11:35:57 volumio volumio[384]: at src/libcore/panicking.rs:85
Feb 25 11:35:57 volumio volumio[384]: 10: 0xa5e478 - core::option::expect_failed::h292a6217b603c24f
Feb 25 11:35:57 volumio volumio[384]: at src/libcore/option.rs:1166
Feb 25 11:35:57 volumio volumio[384]: 11: 0x57b8e0 - <librespot_playback::mixer::alsamixer::AlsaMixer as librespot_playback::mixer::Mixer>::open::hb29b91d9a2daf069
Feb 25 11:35:57 volumio volumio[384]: 12: 0x4a7430 - librespot_playback::mixer::mk_sink::h6af7200b33ccd82d
Feb 25 11:35:57 volumio volumio[384]: 13: 0x4b1208 - <vollibrespot::Main as futures::future::Future>::poll::hb49550d8e3f467fa
Feb 25 11:35:57 volumio volumio[384]: 14: 0x4d84e4 - futures::task_impl::std::set::hb572c3af727256ac
Feb 25 11:35:57 volumio volumio[384]: 15: 0x4af6e8 - <futures::future::lazy::Lazy<F,R> as futures::future::Future>::poll::hc872efa618c45de3
Feb 25 11:35:57 volumio volumio[384]: 16: 0x4d8368 - futures::task_impl::std::set::ha1da852080a54e89
Feb 25 11:35:57 volumio volumio[384]: 17: 0x49ba80 - std::thread::local::LocalKey<T>::with::hb33a14aa0d64830e
Feb 25 11:35:57 volumio volumio[384]: 18: 0x4917a0 - tokio_current_thread::Entered<P>::block_on::h6c7f92e99b77886b
Feb 25 11:35:57 volumio volumio[384]: 19: 0x49b898 - std::thread::local::LocalKey<T>::with::h9ec9ec76b26e7edf
Feb 25 11:35:57 volumio volumio[384]: 20: 0x49b500 - std::thread::local::LocalKey<T>::with::h26f52d592cd722ab
Feb 25 11:35:57 volumio volumio[384]: 21: 0x49b358 - std::thread::local::LocalKey<T>::with::h22d8fcf69243240c
Feb 25 11:35:57 volumio systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a
Feb 25 11:35:57 volumio systemd[1]: Unit volspotconnect2.service entered failed state.
Feb 25 11:35:57 volumio volumio[384]: 22: 0x490d70 - scoped_tls::ScopedKey<T>::set::h3380ded7e37a7882
Feb 25 11:35:57 volumio volumio[384]: 23: 0x4cc3dc - tokio_core::reactor::Core::run::h9c6fa799f1a72320
Feb 25 11:35:57 volumio volumio[384]: 24: 0x4b3cd4 - vollibrespot::main::h551d8fa54606fabf
Feb 25 11:35:57 volumio volumio[384]: 25: 0x4bab84 - std::rt::lang_start::{{closure}}::hdc0b123e45936b4e
Feb 25 11:35:57 volumio volumio[384]: 26: 0xa44fe4 - std::rt::lang_start_internal::{{closure}}::h923917fc45a67b03
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/rt.rs:49
Feb 25 11:35:57 volumio volumio[384]: 27: 0xa44fe4 - std::panicking::try::do_call::he118fbfc301d3e1a
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:296
Feb 25 11:35:57 volumio volumio[384]: 28: 0xa4959c - __rust_maybe_catch_panic
Feb 25 11:35:57 volumio volumio[384]: at src/libpanic_unwind/lib.rs:80
Feb 25 11:35:57 volumio volumio[384]: 29: 0xa45a44 - std::panicking::try::hcc03ea850c2702cb
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panicking.rs:275
Feb 25 11:35:57 volumio volumio[384]: 30: 0xa45a44 - std::panic::catch_unwind::hf09eaf9043e449c8
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/panic.rs:394
Feb 25 11:35:57 volumio volumio[384]: 31: 0xa45a44 - std::rt::lang_start_internal::h87508684140f3dc4
Feb 25 11:35:57 volumio volumio[384]: at src/libstd/rt.rs:48
Feb 25 11:35:57 volumio volumio[384]: 32: 0x4b4cd8 - main
Feb 25 11:35:57 volumio volumio[384]: 33: 0xb6d21294 - __libc_start_main
Feb 25 11:35:57 volumio volumio[384]: [Vollibrespot] librespot_core::session: drop Session[0]
Feb 25 11:35:57 volumio volumio[384]: [Vollibrespot] librespot_core::session: drop Dispatch
Feb 25 11:35:59 volumio systemd[1]: volspotconnect2.service holdoff time over, scheduling restart.
Feb 25 11:35:59 volumio systemd[1]: Stopping Volspotconnect2 Daemon...
Feb 25 11:35:59 volumio systemd[1]: Starting Volspotconnect2 Daemon...
Feb 25 11:35:59 volumio systemd[1]: Started Volspotconnect2 Daemon.
Feb 25 11:36:00 volumio volumio[2808]: vollibrespot v0.1.9 c98fd5d 2019-11-08 (librespot 4674946 2019-11-08) -- Built On 2019-11-08
Feb 25 11:36:00 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:37755
Feb 25 11:36:00 volumio volumio[2808]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] : Login error for user "neoben.86": MAC mismatch
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:36:19 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: Some("action=getInfo")
Feb 25 11:36:23 volumio volumio[2808]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:36:23 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:36:23 volumio volumio[2808]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:36:23 volumio volumio[2808]: [Vollibrespot] : Connecting to AP "gew1-accesspoint-a-l0n2.ap.spotify.com:4070"
Feb 25 11:36:24 volumio volumio[2808]: [Vollibrespot] : Authenticated as "neoben.86" !
Feb 25 11:36:24 volumio volumio[2808]: [Vollibrespot] librespot_core::session: new Session[0]
Feb 25 11:36:24 volumio volumio[2808]: [Vollibrespot] : Setting up new mixer: card:hw:0 mixer:Digital index:0
Feb 25 11:36:24 volumio volumio[2808]: thread 'main' panicked at 'Couldn't find SelemId', src/libcore/option.rs:1166:5
Feb 25 11:36:24 volumio volumio[2808]: stack backtrace:
Feb 25 11:36:25 volumio volumio[2808]: 0: 0xa90df8 - backtrace::backtrace::libunwind::trace::h89fcc71e59e3bc5b
Feb 25 11:36:25 volumio volumio[2808]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/libunwind.rs:88
Feb 25 11:36:25 volumio volumio[2808]: 1: 0xa90df8 - backtrace::backtrace::trace_unsynchronized::h244e30b4d61a86e0
Feb 25 11:36:25 volumio volumio[2808]: at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.34/src/backtrace/mod.rs:66
Feb 25 11:36:25 volumio volumio[2808]: 2: 0xa90df8 - std::sys_common::backtrace::_print::h978df54e55c6209d
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/sys_common/backtrace.rs:47
Feb 25 11:36:25 volumio volumio[2808]: 3: 0xa90df8 - std::sys_common::backtrace::print::ha75ae47f14b8f7f3
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/sys_common/backtrace.rs:36
Feb 25 11:36:25 volumio volumio[2808]: 4: 0xa90df8 - std::panicking::default_hook::{{closure}}::h004e1d529e652ede
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:200
Feb 25 11:36:25 volumio volumio[2808]: 5: 0xa909dc - std::panicking::default_hook::h185ef7ff1eea4221
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:214
Feb 25 11:36:25 volumio volumio[2808]: 6: 0xa915b4 - std::panicking::rust_panic_with_hook::hfe0a86ed15580d4a
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:477
Feb 25 11:36:25 volumio volumio[2808]: 7: 0xa91180 - std::panicking::continue_panic_fmt::h182e68ecbb1c932b
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:384
Feb 25 11:36:25 volumio volumio[2808]: 8: 0xa9106c - rust_begin_unwind
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:311
Feb 25 11:36:25 volumio volumio[2808]: 9: 0xaaa40c - core::panicking::panic_fmt::h7e9f94035af782b3
Feb 25 11:36:25 volumio volumio[2808]: at src/libcore/panicking.rs:85
Feb 25 11:36:25 volumio volumio[2808]: 10: 0xaaa478 - core::option::expect_failed::h292a6217b603c24f
Feb 25 11:36:25 volumio volumio[2808]: at src/libcore/option.rs:1166
Feb 25 11:36:25 volumio volumio[2808]: 11: 0x5c78e0 - <librespot_playback::mixer::alsamixer::AlsaMixer as librespot_playback::mixer::Mixer>::open::hb29b91d9a2daf069
Feb 25 11:36:25 volumio volumio[2808]: 12: 0x4f3430 - librespot_playback::mixer::mk_sink::h6af7200b33ccd82d
Feb 25 11:36:25 volumio volumio[2808]: 13: 0x4fd208 - <vollibrespot::Main as futures::future::Future>::poll::hb49550d8e3f467fa
Feb 25 11:36:25 volumio volumio[2808]: 14: 0x5244e4 - futures::task_impl::std::set::hb572c3af727256ac
Feb 25 11:36:25 volumio volumio[2808]: 15: 0x4fb6e8 - <futures::future::lazy::Lazy<F,R> as futures::future::Future>::poll::hc872efa618c45de3
Feb 25 11:36:25 volumio volumio[2808]: 16: 0x524368 - futures::task_impl::std::set::ha1da852080a54e89
Feb 25 11:36:25 volumio volumio[2808]: 17: 0x4e7a80 - std::thread::local::LocalKey<T>::with::hb33a14aa0d64830e
Feb 25 11:36:25 volumio volumio[2808]: 18: 0x4dd7a0 - tokio_current_thread::Entered<P>::block_on::h6c7f92e99b77886b
Feb 25 11:36:25 volumio systemd[1]: volspotconnect2.service: main process exited, code=exited, status=101/n/a
Feb 25 11:36:25 volumio systemd[1]: Unit volspotconnect2.service entered failed state.
Feb 25 11:36:25 volumio volumio[2808]: 19: 0x4e7898 - std::thread::local::LocalKey<T>::with::h9ec9ec76b26e7edf
Feb 25 11:36:25 volumio volumio[2808]: 20: 0x4e7500 - std::thread::local::LocalKey<T>::with::h26f52d592cd722ab
Feb 25 11:36:25 volumio volumio[2808]: 21: 0x4e7358 - std::thread::local::LocalKey<T>::with::h22d8fcf69243240c
Feb 25 11:36:25 volumio volumio[2808]: 22: 0x4dcd70 - scoped_tls::ScopedKey<T>::set::h3380ded7e37a7882
Feb 25 11:36:25 volumio volumio[2808]: 23: 0x5183dc - tokio_core::reactor::Core::run::h9c6fa799f1a72320
Feb 25 11:36:25 volumio volumio[2808]: 24: 0x4ffcd4 - vollibrespot::main::h551d8fa54606fabf
Feb 25 11:36:25 volumio volumio[2808]: 25: 0x506b84 - std::rt::lang_start::{{closure}}::hdc0b123e45936b4e
Feb 25 11:36:25 volumio volumio[2808]: 26: 0xa90fe4 - std::rt::lang_start_internal::{{closure}}::h923917fc45a67b03
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/rt.rs:49
Feb 25 11:36:25 volumio volumio[2808]: 27: 0xa90fe4 - std::panicking::try::do_call::he118fbfc301d3e1a
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:296
Feb 25 11:36:25 volumio volumio[2808]: 28: 0xa9559c - __rust_maybe_catch_panic
Feb 25 11:36:25 volumio volumio[2808]: at src/libpanic_unwind/lib.rs:80
Feb 25 11:36:25 volumio volumio[2808]: 29: 0xa91a44 - std::panicking::try::hcc03ea850c2702cb
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panicking.rs:275
Feb 25 11:36:25 volumio volumio[2808]: 30: 0xa91a44 - std::panic::catch_unwind::hf09eaf9043e449c8
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/panic.rs:394
Feb 25 11:36:25 volumio volumio[2808]: 31: 0xa91a44 - std::rt::lang_start_internal::h87508684140f3dc4
Feb 25 11:36:25 volumio volumio[2808]: at src/libstd/rt.rs:48
Feb 25 11:36:25 volumio volumio[2808]: 32: 0x500cd8 - main
Feb 25 11:36:25 volumio volumio[2808]: 33: 0xb6ce6294 - __libc_start_main
Feb 25 11:36:25 volumio volumio[2808]: [Vollibrespot] librespot_core::session: drop Session[0]
Feb 25 11:36:25 volumio volumio[2808]: [Vollibrespot] librespot_core::session: drop Dispatch
Feb 25 11:36:27 volumio systemd[1]: volspotconnect2.service holdoff time over, scheduling restart.
Feb 25 11:36:27 volumio systemd[1]: Stopping Volspotconnect2 Daemon...
Feb 25 11:36:27 volumio systemd[1]: Starting Volspotconnect2 Daemon...
Feb 25 11:36:27 volumio systemd[1]: Started Volspotconnect2 Daemon.
Feb 25 11:36:27 volumio volumio[2900]: vollibrespot v0.1.9 c98fd5d 2019-11-08 (librespot 4674946 2019-11-08) -- Built On 2019-11-08
Feb 25 11:36:28 volumio volumio[2900]: [Vollibrespot] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:38385
Feb 25 11:36:28 volumio volumio[2900]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }
Feb 25 11:36:45 volumio volumio[2900]: [Vollibrespot] : ConnectRequest: "Spotify/112600501 Linux/0 (PC desktop)"
Feb 25 11:36:45 volumio volumio[2900]: [Vollibrespot] librespot_connect::discovery: ConnectRequest: None
Feb 25 11:36:45 volumio volumio[2900]: [Vollibrespot] librespot_connect::discovery: POST "/" {}
Feb 25 11:36:45 volumio volumio[2900]: [Vollibrespot] : Login error for user "neoben.86": MAC mismatch
Thanks!
Look like the old issue with finding the right mixer. (thread ‘main’ panicked at ‘Couldn’t find SelemId’)
What is your Output/Mixer setup in Volumio?
Whats the output of
aplay -l
cat /data/plugins/music_service/volspotconnect2/startconnect.shPS: remove passwords from startconnect.sh if you don’t use Multiuser
Here it is!
volumio@volumio:~$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: ALSA [bcm2835 ALSA], device 0: bcm2835 ALSA [bcm2835 ALSA]
Subdevices: 7/7
Subdevice #0: subdevice #0
Subdevice #1: subdevice #1
Subdevice #2: subdevice #2
Subdevice #3: subdevice #3
Subdevice #4: subdevice #4
Subdevice #5: subdevice #5
Subdevice #6: subdevice #6
card 0: ALSA [bcm2835 ALSA], device 1: bcm2835 IEC958/HDMI [bcm2835 IEC958/HDMI]
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: ALSA [bcm2835 ALSA], device 2: bcm2835 IEC958/HDMI1 [bcm2835 IEC958/HDMI1]
Subdevices: 1/1
Subdevice #0: subdevice #0
volumio@volumio:~$ cat /data/plugins/music_service/volspotconnect2/startconnect.sh
#this file is generated by the plugin. You should not edit it unless you know what you do. It will be overwritten by the plugin each time a change in config is detected
cd /data/plugins/music_service/volspotconnect2
./vollibrespot -b 320 -c /tmp \
--disable-audio-cache \
--name 'Volumio' --initial-volume 0\
--device plughw:0 \
--mixer alsa \
--mixer-name 'Digital' --mixer-card 'hw:0' \
--verbose
I tried to disable I2S DAC and now it is working.
Do you have any particular suggestion for I2S DAC configuration e.g. (output setting to use)?
Looks like the mixer Digital is wrong. IIRC, it should be Master for card 0 (bcm2835 ALSA) that is chosen currently.
This can be checked from
amixer
amixer controlsIMHO there was/is some issue/race condition with the api used internally from Volumio by the plugin that we need to investigate - it requires a re confirmation of the mixer for it to show up correctly.
Not sure by what you mean - if you have a DAC hooked up and working normally with MPD, it should work fine with the plugin…
volumio@volumio:~$ amixer
Simple mixer control 'PCM',0
Capabilities: pvolume pvolume-joined pswitch pswitch-joined
Playback channels: Mono
Limits: Playback -10239 - 400
Mono: Playback 400 [100%] [4.00dB] [on]
volumio@volumio:~$ amixer controls
numid=3,iface=MIXER,name='PCM Playback Route'
numid=2,iface=MIXER,name='PCM Playback Switch'
numid=1,iface=MIXER,name='PCM Playback Volume'
numid=5,iface=PCM,name='IEC958 Playback Con Mask'
numid=4,iface=PCM,name='IEC958 Playback Default'
If you go to the Playback settings page, and reconfigure your mixer, the plugin should automatically pick up the new mixer and updated the DIGITAL -> PCM. Else, manually edit startconnect.sh and change Digital to PCM.
This apparently doesn’t work always smoothly the first time, especially when switching outputs (I2S to Analog jack for example) and needs to be investigated. If you can reproduce it, would request you to share the steps to trigger the issue!
Setting Audio Output --> I2S DAC from On to Off fixed the issue in first instance.
If I put I2S DAC to on again the Output Device goes to Adafruit Max98357 (before the last fw upgrade the list of available outputs was quite longer).
Anyway with this kind of configuration it seems to work properly.
Do you want me to look for any other dubug info in order to help with the troubleshoot?
Ok, I have something new.
After rebooting the device I got a longer list for DAC Model in Playback Settings --> Audio Output.
I selected as DAC Model Volumio ESS 9028QM and saved.
Unfortunately in the Volume Option Tab it’s impossible to select the Mixer Control Name: by default it is selected on Digital but clicking on the dropdown menu makes the field transparent so it’s impossible to select any other option different from Digital.
I suppose that the only way is to change it manually.
Let me know if you need more detailed info.
Thanks!
What DAC do you have? I’m guessing your on a PiZero - shouldn’t there should be more devices I2S devices visible from the drop-down menu?
Clearing up some confusion each device has a corresponding mixer, as long the right device and mixer are selected, it should work.
Analog Jack => Mixer = PCM
ESS 9028QM => Mixer = Digital
The issue you faced was when you probably switched back from I2S to analog, and the mixer didn’t automatically update?
Correct!