Raspotify works but no sound played with spotify-skill

sigur_ros21 · November 1, 2021, 6:49pm

Spotify Skill (see GitHub - forslund/spotify-skill: Mycroft Skill to control spotify using the Spotify Connect API)
Picroft release candidate on a Raspberry Pi 4B, 4GB RAM.
Using WM8960 Audio HAT as input/output audio device.

Hello,

I have trouble with the Spotify skill on Picroft (see hardware platform and OS details above). I can play anything from my Spotify client on my laptop selecting my picroft device and it sounds just fine. However, when I ask mycroft to play any song, I can see that Spotify is playing a song but no sound is coming from my picroft device.

Looking at the raspotify logs, it appears that mycroft is failing in getting ahold of the audio device. I have tried setting up the --device option to hw:0,0 but it doesn’t work.

A few details about my systems’ installation:

Audio setup:

I had trouble setting up the audio. After installing the drivers, I (1) blacklisted the raspberry pi’s default audio module so that only the wm8960 device is loaded; (2) resorted to using “sudo aplay %1” in the pycroft configuration as otherwise it would’t work.

Spotify skill setup

Installing the skill directly from the marketplace wouldn’t work because of authentication issues.
I installed the skill using the instructions in GitHub - forslund/spotify-skill: Mycroft Skill to control spotify using the Spotify Connect API.

The logs from raspotify:

Nov 01 16:10:06 picroft systemd[1]: Started Raspotify.
Nov 01 16:10:06 picroft librespot[3260]: [2021-11-01T16:10:06Z INFO  librespot] librespot (raspotify v0.16.0) 0adb851 (2020-12-15). Built on 2020-12-30. Build ID: KLdkAvgt
Nov 01 16:10:06 picroft librespot[3260]: [2021-11-01T16:10:06Z INFO  librespot_core::session] Connecting to AP "gew1-accesspoint-a-r6tw.ap.spotify.com:4070"
Nov 01 16:10:06 picroft librespot[3260]: [2021-11-01T16:10:06Z INFO  librespot_core::session] Authenticated as "<myusername>" !
Nov 01 16:10:06 picroft librespot[3260]: [2021-11-01T16:10:06Z INFO  librespot_playback::audio_backend::alsa] Using alsa sink
Nov 01 16:10:06 picroft librespot[3260]: [2021-11-01T16:10:06Z INFO  librespot_core::session] Country: "GB"
Nov 01 16:10:25 picroft librespot[3260]: [2021-11-01T16:10:25Z INFO  librespot_playback::player] Loading <Right on Time> with Spotify URI <spotify:track:5i4WgW0TL9VSosy73Q3Ttv>
Nov 01 16:10:26 picroft librespot[3260]: [2021-11-01T16:10:26Z INFO  librespot_playback::player] <Right on Time> (185228 ms) loaded
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::audio_backend::alsa] Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::player] Could not start audio: Alsa error: PCM open failed
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::audio_backend::alsa] Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::player] Could not start audio: Alsa error: PCM open failed
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::audio_backend::alsa] Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
Nov 01 16:10:27 picroft librespot[3260]: [2021-11-01T16:10:27Z ERROR librespot_playback::player] Could not start audio: Alsa error: PCM open failed
Nov 01 16:10:27 picroft librespot[3260]: thread '<unnamed>' panicked at 'called `Option::unwrap()` on a `None` value', playback/src/audio_backend/alsa.rs:138:45
Nov 01 16:10:27 picroft librespot[3260]: stack backtrace:
Nov 01 16:10:27 picroft librespot[3260]:    0:   0x89a278 - std::backtrace_rs::backtrace::libunwind::trace::h9c6af82ecb947420
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/libunwind.rs:96
Nov 01 16:10:27 picroft librespot[3260]:    1:   0x89a278 - std::backtrace_rs::backtrace::trace_unsynchronized::h80561bf66e637b12
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/mod.rs:66
Nov 01 16:10:27 picroft librespot[3260]:    2:   0x89a278 - std::sys_common::backtrace::_print_fmt::h8904fddc87bf6b5e
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:79
Nov 01 16:10:27 picroft librespot[3260]:    3:   0x89a278 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hc883ceb7a13219f2
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:58
Nov 01 16:10:27 picroft librespot[3260]:    4:   0x8c2290 - core::fmt::write::ha75209c8e86bef45
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/fmt/mod.rs:1080
Nov 01 16:10:27 picroft librespot[3260]:    5:   0x892e18 - std::io::Write::write_fmt::h4cce8be81a41c537
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/io/mod.rs:1516
Nov 01 16:10:27 picroft librespot[3260]:    6:   0x89d1c0 - std::sys_common::backtrace::_print::hdc9e28891c09ab0b
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:61
Nov 01 16:10:27 picroft librespot[3260]:    7:   0x89d1c0 - std::sys_common::backtrace::print::h85895381379b4dc1
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:48
Nov 01 16:10:27 picroft librespot[3260]:    8:   0x89d1c0 - std::panicking::default_hook::{{closure}}::h6b4de484f2428118
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:208
Nov 01 16:10:27 picroft librespot[3260]:    9:   0x89cdbc - std::panicking::default_hook::h3966366a200b03f1
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:227
Nov 01 16:10:27 picroft librespot[3260]:   10:   0x89d910 - std::panicking::rust_panic_with_hook::h068b5368b0949ced
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:577
Nov 01 16:10:27 picroft librespot[3260]:   11:   0x89d4c4 - std::panicking::begin_panic_handler::{{closure}}::hde463ebfc6f96538
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:484
Nov 01 16:10:27 picroft librespot[3260]:   12:   0x89a7f8 - std::sys_common::backtrace::__rust_end_short_backtrace::hb945924c40726c97
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:153
Nov 01 16:10:27 picroft librespot[3260]:   13:   0x89d47c - rust_begin_unwind
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:483
Nov 01 16:10:27 picroft librespot[3260]:   14:   0x8bf960 - core::panicking::panic_fmt::h27b19d6e6dedd33e
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:85
Nov 01 16:10:27 picroft librespot[3260]:   15:   0x8bf8bc - core::panicking::panic::h2a6f9b05d102de10
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:50
Nov 01 16:10:27 picroft librespot[3260]:   16:   0x526020 - <librespot_playback::audio_backend::alsa::AlsaSink as librespot_playback::audio_backend::Sink>::write::hfb124b87fed1cc15
Nov 01 16:10:27 picroft librespot[3260]:   17:   0x503304 - <librespot_playback::player::PlayerInternal as futures::future::Future>::poll::he6e04a5bccf94e34
Nov 01 16:10:27 picroft librespot[3260]:   18:   0x467300 - futures::task_impl::std::set::hab1c1811473e3998
Nov 01 16:10:27 picroft librespot[3260]:   19:   0x45d838 - std::sys_common::backtrace::__rust_begin_short_backtrace::h8286c5a0fd04a387
Nov 01 16:10:27 picroft librespot[3260]:   20:   0x4784f4 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h76e6c7604d7daced
Nov 01 16:10:27 picroft librespot[3260]:   21:   0x8a4940 - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h6b7ad05f87ff90ae
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/boxed.rs:1042
Nov 01 16:10:27 picroft librespot[3260]:   22:   0x8a4940 - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::he9130e675b8d97ee
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/alloc/src/boxed.rs:1042
Nov 01 16:10:27 picroft librespot[3260]:   23:   0x8a4940 - std::sys::unix::thread::Thread::new::thread_start::h7a3f6590d8e03e95
Nov 01 16:10:27 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys/unix/thread.rs:87
Nov 01 16:10:35 picroft librespot[3260]: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', playback/src/player.rs:281:61
Nov 01 16:10:35 picroft librespot[3260]: stack backtrace:
Nov 01 16:10:35 picroft librespot[3260]:    0:   0x89a278 - std::backtrace_rs::backtrace::libunwind::trace::h9c6af82ecb947420
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/libunwind.rs:96
Nov 01 16:10:35 picroft librespot[3260]:    1:   0x89a278 - std::backtrace_rs::backtrace::trace_unsynchronized::h80561bf66e637b12
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/../../backtrace/src/backtrace/mod.rs:66
Nov 01 16:10:35 picroft librespot[3260]:    2:   0x89a278 - std::sys_common::backtrace::_print_fmt::h8904fddc87bf6b5e
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:79
Nov 01 16:10:35 picroft librespot[3260]:    3:   0x89a278 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hc883ceb7a13219f2
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:58
Nov 01 16:10:35 picroft librespot[3260]:    4:   0x8c2290 - core::fmt::write::ha75209c8e86bef45
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/fmt/mod.rs:1080
Nov 01 16:10:35 picroft librespot[3260]:    5:   0x892e18 - std::io::Write::write_fmt::h4cce8be81a41c537
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/io/mod.rs:1516
Nov 01 16:10:35 picroft librespot[3260]:    6:   0x89d1c0 - std::sys_common::backtrace::_print::hdc9e28891c09ab0b
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:61
Nov 01 16:10:35 picroft librespot[3260]:    7:   0x89d1c0 - std::sys_common::backtrace::print::h85895381379b4dc1
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:48
Nov 01 16:10:35 picroft librespot[3260]:    8:   0x89d1c0 - std::panicking::default_hook::{{closure}}::h6b4de484f2428118
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:208
Nov 01 16:10:35 picroft librespot[3260]:    9:   0x89cdbc - std::panicking::default_hook::h3966366a200b03f1
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:227
Nov 01 16:10:35 picroft librespot[3260]:   10:   0x89d910 - std::panicking::rust_panic_with_hook::h068b5368b0949ced
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:577
Nov 01 16:10:35 picroft librespot[3260]:   11:   0x89d4c4 - std::panicking::begin_panic_handler::{{closure}}::hde463ebfc6f96538
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:484
Nov 01 16:10:35 picroft librespot[3260]:   12:   0x89a7f8 - std::sys_common::backtrace::__rust_end_short_backtrace::hb945924c40726c97
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:153
Nov 01 16:10:35 picroft librespot[3260]:   13:   0x89d47c - rust_begin_unwind
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:483
Nov 01 16:10:35 picroft librespot[3260]:   14:   0x8bf960 - core::panicking::panic_fmt::h27b19d6e6dedd33e
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/panicking.rs:85
Nov 01 16:10:35 picroft librespot[3260]:   15:   0x8bf7b8 - core::option::expect_none_failed::h0ec77a052e666b69
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/option.rs:1234
Nov 01 16:10:35 picroft librespot[3260]:   16:   0x5000a8 - librespot_playback::player::Player::pause::h4bd7037998ab1226
Nov 01 16:10:35 picroft librespot[3260]:   17:   0x4af590 - librespot_connect::spirc::SpircTask::handle_pause::had01063f6bb2c635
Nov 01 16:10:35 picroft librespot[3260]:   18:   0x4ada34 - <librespot_connect::spirc::SpircTask as futures::future::Future>::poll::h400d0c6a9af9b895
Nov 01 16:10:35 picroft librespot[3260]:   19:   0x473ab4 - <librespot::Main as futures::future::Future>::poll::h169a5d4027f550f1
Nov 01 16:10:35 picroft librespot[3260]:   20:   0x466cf0 - futures::task_impl::std::set::h171bb0e3315231c5
Nov 01 16:10:35 picroft librespot[3260]:   21:   0x4855b0 - <futures::future::lazy::Lazy<F,R> as futures::future::Future>::poll::h6ad5d06c62a954b1
Nov 01 16:10:35 picroft librespot[3260]:   22:   0x466e70 - futures::task_impl::std::set::h1b4107da043418f3
Nov 01 16:10:35 picroft librespot[3260]:   23:   0x45dc1c - std::thread::local::LocalKey<T>::with::h10f666118935c490
Nov 01 16:10:35 picroft librespot[3260]:   24:   0x45c6b8 - tokio_current_thread::Entered<P>::block_on::hbb47725fa57f8e44
Nov 01 16:10:35 picroft librespot[3260]:   25:   0x4635b8 - tokio_timer::timer::handle::with_default::h938751ab893a9316
Nov 01 16:10:35 picroft librespot[3260]:   26:   0x45dff8 - std::thread::local::LocalKey<T>::with::hed23bc0e3035947a
Nov 01 16:10:35 picroft librespot[3260]:   27:   0x45b990 - scoped_tls::ScopedKey<T>::set::heda756cd7e82ddd6
Nov 01 16:10:35 picroft librespot[3260]:   28:   0x462cf0 - tokio_core::reactor::Core::run::hccb77cd75ccb2c67
Nov 01 16:10:35 picroft librespot[3260]:   29:   0x476448 - librespot::main::h6da7c78e457a1f2f
Nov 01 16:10:35 picroft librespot[3260]:   30:   0x45dabc - std::sys_common::backtrace::__rust_begin_short_backtrace::h92f05e3879870930
Nov 01 16:10:35 picroft librespot[3260]:   31:   0x48030c - std::rt::lang_start::{{closure}}::h067bf4c6ab425fd6
Nov 01 16:10:35 picroft librespot[3260]:   32:   0x89dd30 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2c136973bfb85920
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:259
Nov 01 16:10:35 picroft librespot[3260]:   33:   0x89dd30 - std::panicking::try::do_call::hc0787118c306af2e
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:381
Nov 01 16:10:35 picroft librespot[3260]:   34:   0x89dd30 - std::panicking::try::he0aeb9ab5f254114
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:345
Nov 01 16:10:35 picroft librespot[3260]:   35:   0x89dd30 - std::panic::catch_unwind::hb91533e13ff48846
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panic.rs:382
Nov 01 16:10:35 picroft librespot[3260]:   36:   0x89dd30 - std::rt::lang_start_internal::hf9465186f7b70c75
Nov 01 16:10:35 picroft librespot[3260]:                        at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:51
Nov 01 16:10:35 picroft librespot[3260]:   37:   0x477460 - main
Nov 01 16:10:35 picroft librespot[3260]:   38: 0xb6ca9718 - __libc_start_main
Nov 01 16:10:35 picroft librespot[3260]: [2021-11-01T16:10:35Z ERROR librespot_playback::player] Player thread panicked!
Nov 01 16:10:35 picroft systemd[1]: raspotify.service: Main process exited, code=exited, status=101/n/a
Nov 01 16:10:35 picroft systemd[1]: raspotify.service: Failed with result 'exit-code'.

Any help is much appreciated. Thank you.

sigur_ros21 · November 24, 2021, 6:52pm

After a while of not looking at this I decided to give it a go and I ended up finding out the issue and fixing it.

I started with a fresh image of Mycroft for Raspberry Pi (same version as in my original post). This time, I installed librespot instead of raspotify. I originally set it up as a system service, but then once I found why picroft would’t respect my wishes playing Spotify, I realise the system service is not really necessary.

So, what was going wrong?

It turns out that opt/mycroft/skills/mycroft-spotify.forslund/__init__.py is programmed to launch librespot if using Mark 1 or Mark 2 only. So… I added a simple modification: I added picroft to MANAGED_PLATFORMS such that:

MANAGED_PLATFORMS = ['mycroft_mark_1', 'mycroft_mark_2pi', 'picroft']

For this to work, create a sym link to librespot in your /usr/bin directory. I had the binary in /opt/librespot/target/release/librespot so I did:

sudo ln -s /opt/librespot/target/release/librespot /usr/bin/librespot

I also took the liberty to modify the following:

self.process = Popen([path, '-n', self.device_name.title(),
                                  '-u', self.settings['user'],
                                  '-p', self.settings['password'],
                                  '-b', "320",
                                  '--device-type', "homething",
                                  '--disable-audio-cache',
                                  '--enable-volume-normalisation',
                                  '--volume-ctrl', 'linear'],
                                 stdout=outs, stderr=outs)

so that librespot would launch with a few other nice-to-have options.

I hope this helps!