Spotify not working (both 0.1.9 and prerelease)

Troubleshooting
1

Hi
I have trouble streaming Spotify to my AmpliPi, I had the problem before and still do after upgrading to the latest pre-release.
After creating the input, it shows up in my Spotify clients (iPhone and PC), but when I try to select it it fails and then then the input disapears from the list.

Here are the logs I am getting in the new version:

Nov 19 08:01:56 amplipi authbind[811]: Connecting to AP "ap.spotify.com:443"
Nov 19 08:01:57 amplipi authbind[811]: Authenticated as "julienc" !
Nov 19 08:01:57 amplipi authbind[811]: Country: "FR"
Nov 19 08:01:57 amplipi authbind[811]: Using Alsa sink with format: S16
Nov 19 08:01:57 amplipi authbind[811]: error 403 for uri hm://keymaster/token/authenticated?client_id=2c1ea498dfbc4a979e2426f4841297c3&scope=user-read-playback-state,user-modify-playback-state,user-read-currently-playing
Nov 19 08:01:57 amplipi authbind[811]: failed to request a token for the web API

And with the old version (I downgraded to get you the logs):

Nov 20 09:52:49 amplipi authbind[812]: vollibrespot v0.2.4 61563b7 2021-07-22 (librespot 08d8bcc 2020-10-07) -- Built On 2021-07-22
Nov 20 09:52:49 amplipi authbind[812]: Reading Config from "config.toml"
Nov 20 09:52:49 amplipi authbind[812]: [Vollibrespot] : Using Alsa backend with device: ch0
Nov 20 09:52:49 amplipi authbind[812]: Spotify Julien disconnected
Nov 20 09:52:49 amplipi authbind[812]: Spotify Julien connected to 0
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Connecting to AP "ap-gue1.spotify.com:443"
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Authenticated as "julienc" !
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Using alsa sink
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Metadata pipe established
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Country: "FR"
Nov 20 09:52:54 amplipi authbind[812]: [Vollibrespot] : Event: Volume { volume_to_mixer: 65535 }
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : Event: SessionActive { became_active_at: 1668955975211 }
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : SessionActive!
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 28572513715581254038467865968562517601, audio_type: Track } }
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 28572513715581254038467865968562517601, audio_type: Track } }
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=4ced2e7c73484127be5d36015752eb43&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : Error: MercuryError
Nov 20 09:52:55 amplipi authbind[812]: thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.31/src/future/map.rs:35:29
Nov 20 09:52:55 amplipi authbind[812]: stack backtrace:
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : Loading <Boogie for Brubeck> with Spotify URI <spotify:track:0EyODHoOgxIdQvBzROIWJP>
Nov 20 09:52:55 amplipi authbind[812]:    0:   0x9c13dc - std::backtrace_rs::backtrace::libunwind::trace::h27f2387a4162a450
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
Nov 20 09:52:55 amplipi authbind[812]:    1:   0x9c13dc - std::backtrace_rs::backtrace::trace_unsynchronized::h163a7502bf6b94aa
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
Nov 20 09:52:55 amplipi authbind[812]:    2:   0x9c13dc - std::sys_common::backtrace::_print_fmt::h43e6d4cedc52f23a
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:67:5
Nov 20 09:52:55 amplipi authbind[812]:    3:   0x9c13dc - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hde8f8384e4e6dbf2
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:46:22
Nov 20 09:52:55 amplipi authbind[812]:    4:   0x9e5fdc - core::fmt::write::he9a84ebd1145a5b6
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/fmt/mod.rs:1094:17
Nov 20 09:52:55 amplipi authbind[812]:    5:   0x9bac50 - std::io::Write::write_fmt::hb674bb2dc2ae8509
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/io/mod.rs:1584:15
Nov 20 09:52:55 amplipi authbind[812]:    6:   0x9c3a28 - std::sys_common::backtrace::_print::he8ac319d646764e6
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:49:5
Nov 20 09:52:55 amplipi authbind[812]:    7:   0x9c3a28 - std::sys_common::backtrace::print::hc642e9974601dbe9
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:36:9
Nov 20 09:52:55 amplipi authbind[812]:    8:   0x9c3a28 - std::panicking::default_hook::{{closure}}::ha1230b816c9262c0
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:208:50
Nov 20 09:52:55 amplipi authbind[812]:    9:   0x9c3414 - std::panicking::default_hook::h7e50a310a4eb3bfa
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:225:9
Nov 20 09:52:55 amplipi authbind[812]:   10:   0x9c406c - std::panicking::rust_panic_with_hook::hec171a86b5342505
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:591:17
Nov 20 09:52:55 amplipi authbind[812]:   11:   0x9c3bec - std::panicking::begin_panic_handler::{{closure}}::h88a5c16da59165d8
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:497:13
Nov 20 09:52:55 amplipi authbind[812]:   12:   0x9c1958 - std::sys_common::backtrace::__rust_end_short_backtrace::h27383fc565bb9434
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/sys_common/backtrace.rs:141:18
Nov 20 09:52:55 amplipi authbind[812]:   13:   0x9c3b34 - rust_begin_unwind
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:493:5
Nov 20 09:52:55 amplipi authbind[812]:   14:   0x4b0efc - core::panicking::panic_fmt::hf038e00ff0a6dc95
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/panicking.rs:92:14
Nov 20 09:52:55 amplipi authbind[812]:   15:   0x4b0e04 - core::option::expect_failed::h1a5b0ed0d7e46508
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/option.rs:1241:5
Nov 20 09:52:55 amplipi authbind[812]:   16:   0x6b1284 - <futures::future::map::Map<A,F> as futures::future::Future>::poll::h4c653c32cfc5717a
Nov 20 09:52:55 amplipi authbind[812]:   17:   0x593f64 - <librespot_connect::spirc::SpircTask as futures::future::Future>::poll::hf00e5f1b2181a8ec
Nov 20 09:52:55 amplipi authbind[812]:   18:   0x4d4268 - <vollibrespot::Main as futures::future::Future>::poll::h11d121524e198aad
Nov 20 09:52:55 amplipi authbind[812]:   19:   0x4f0b58 - futures::task_impl::std::set::hf70ca65bf0ab6774
Nov 20 09:52:55 amplipi authbind[812]:   20:   0x50a908 - std::thread::local::LocalKey<T>::with::hda6b6968b2135d62
Nov 20 09:52:55 amplipi authbind[812]:   21:   0x4e2cac - tokio_current_thread::Entered<P>::block_on::h462d509ec5837667
Nov 20 09:52:55 amplipi authbind[812]:   22:   0x50a49c - std::thread::local::LocalKey<T>::with::h93ec4fc523c83303
Nov 20 09:52:55 amplipi authbind[812]:   23:   0x51fb98 - tokio_timer::timer::handle::with_default::hb988719f051bcea1
Nov 20 09:52:55 amplipi authbind[812]:   24:   0x507fb8 - tokio_reactor::with_default::hbb621881a2c902fa
Nov 20 09:52:55 amplipi authbind[812]:   25:   0x4e8080 - tokio::runtime::current_thread::runtime::Runtime::block_on::hecddce3e624c1d75
Nov 20 09:52:55 amplipi authbind[812]:   26:   0x4d69e0 - vollibrespot::main::he59b9fa9669963c0
Nov 20 09:52:55 amplipi authbind[812]:   27:   0x508e48 - std::sys_common::backtrace::__rust_begin_short_backtrace::h44b8a67fc3813b6a
Nov 20 09:52:55 amplipi authbind[812]:   28:   0x509604 - std::rt::lang_start::{{closure}}::hdb667105a10c2bb7
Nov 20 09:52:55 amplipi authbind[812]:   29:   0x9c4468 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h837fd2b0758830d5
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/core/src/ops/function.rs:259:13
Nov 20 09:52:55 amplipi authbind[812]:   30:   0x9c4468 - std::panicking::try::do_call::hcf325a9f3885337b
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:379:40
Nov 20 09:52:55 amplipi authbind[812]:   31:   0x9c4468 - std::panicking::try::h1494c76488c08e1c
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panicking.rs:343:19
Nov 20 09:52:55 amplipi authbind[812]:   32:   0x9c4468 - std::panic::catch_unwind::h32a7251e05893da7
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/panic.rs:431:14
Nov 20 09:52:55 amplipi authbind[812]:   33:   0x9c4468 - std::rt::lang_start_internal::hcdbc213228e2ca56
Nov 20 09:52:55 amplipi authbind[812]:                        at /rustc/53cb7b09b00cbea8754ffb78e7e3cb521cb8af4b/library/std/src/rt.rs:34:21
Nov 20 09:52:55 amplipi authbind[812]:   34:   0x4d8194 - main
Nov 20 09:52:55 amplipi authbind[812]:   35: 0x76bac718 - __libc_start_main
Nov 20 09:52:55 amplipi authbind[812]: [Vollibrespot] : EventSender disconnected

Note that I do have a premium account and have never had trouble streaming to my TV and various other devices. Airplay works from the phone, but involves a couple more clicks, and it is not an option from my PC…

Spotify also used to work on my AmpliPi. Usually for a few weeks after a hard reboot…

Spotify channels unreachable since 0.3.4
2

Sorry you are having trouble with our Spotify integration. We have not seen this failure before.

The Spotify prerelease was built off of the latest code in the Spotifyd repo, I wonder is anyone else there is seeing this issue.

3

Are there any spotify account restrictions to be able use the amplipi spotify input as a target in the spotify app? I ask as I can see the amplipi spotify target from my spotify android app, but it’s greyed out and listed as “unavailable for listening on”

v0.1.9+lms-beta2

4

The only restriction is having a Spotify premium account. If you get a chance feel free to checkout the spotify prerelease: Release Spotify Upgrade - Prerelease · micro-nova/AmpliPi · GitHub that uses a newer Spotify client, it seems to have better integration.

5

I found a workaround to my Spotify issue: if I connect my Spotify client to the AmpliPi source while a song is playing on Spotify, it does connect and work properly. But it still fails when I try to connect while nothing is playing.

I’m on v0.1.9+spotifyd-beta1.

6

it still fails when I try to connect while nothing is playing

Hmm, we are still not able to reproduce this. We tried with various iPhones and even an iPad.

7

I’m still running into amplipi not being selectable from my spotify instances pretty regularly. Rebooting the amplipi brings it back. Is there any diag data I can collect to help figure it out? I’ve been running 0.2.1 and the ‘spotify update’ branch as well and have been getting unreliable behavior using both.

8

This simplest thing you can do is send us the output from http://amplipi.local:19531/entries before restarting (it gets cleared out on a reboot). There is a link at the bottom of the ui called logs that also takes you to the same place.

9

I’m getting a TON of this repeating:

Oct 04 16:52:18 amplipi authbind[585]: ALSA lib pcm_direct.c:1824:(_snd_pcm_direct_get_slave_ipc_offset) Invalid value for card
Oct 04 16:52:18 amplipi authbind[585]: playback ch3 open error: No such device
Oct 04 16:52:18 amplipi authbind[585]: Loopback initialization failure.
Oct 04 16:52:18 amplipi authbind[585]: Subprocess exited with non-zero code: 1. Restarting…
Oct 04 16:52:18 amplipi authbind[585]: ALSA lib pcm_direct.c:1824:(_snd_pcm_direct_get_slave_ipc_offset) Invalid value for card
Oct 04 16:52:18 amplipi authbind[585]: playback ch3 open error: No such device
Oct 04 16:52:18 amplipi authbind[585]: Loopback initialization failure.
Oct 04 16:52:18 amplipi authbind[585]: Subprocess exited with non-zero code: 1. Restarting…

Doesn’t seem spotify specific. At the moment, I’m able to connect to it but without any audio.

10

How many things do you have plugged into AmpliPi’s USB ports?

11

I don’t have anything plugged into the USB ports.

I toggled the zones off and back on and I’m back in action.

12

same error here no usb no nothing tried also post Issues after upgrading to 0.3.0 - #4 by linknum23 no luck …

13

Hey Stamate!

Can you validate what version of AmpliPi you’re running by going to Settings → About → Version? Spotify has been updating their API a lot lately which has caused us to have two updates just to bump our Spotify client version, the most recent being 0.4.8

14

Hey i am not using the spotify its about the

(_snd_pcm_direct_get_slave_ipc_offset) Invalid value for card
Oct 04 16:52:18 amplipi authbind[585]: playback ch3 open error: No such device

Anyways i have another problem that output does nothing no sound so i found this now:

System Information

  • Device: AmpliPi

  • Uptime: ~12.5 hours

  • Load Average: 1.52, 1.24, 1.19 (4-core system)

  • Memory: 923 MiB total, ~92 MiB free

Dec 12 15:25:30 amplipi authbind[797]: overrun for capture lb2p
Dec 12 15:25:29 amplipi authbind[797]: overrun for capture lb2p

Two alsaloop instances are running with different behavior:

Normal process (PID 1231):

  • Command: alsaloop -C lb1p -P ch0 -t 100000

  • CPU Usage: 2.8%

  • State: SL (sleeping/locked)

  • Runtime: 21:15 minutes

Problematic process (PID 1313):

  • Command: alsaloop -C lb2p -P ch1 -t 100000

  • CPU Usage: 24.7% (peaked at 86.4%)

  • State: RL (running/locked)

  • Runtime: 185:05 minutes

  • Behavior: Appears stuck in runaway state

pi        1225  0.0  0.7  14176  7148 ?        S    03:01   0:00 /home/pi/amplipi-dev/venv/bin/python /home/pi/amplipi-dev/streams/process_monitor.py alsaloop -C lb1p -P ch0 -t 100000
pi        1227  0.0  0.7  14176  7136 ?        S    03:01   0:00 /home/pi/amplipi-dev/venv/bin/python /home/pi/amplipi-dev/streams/process_monitor.py alsaloop -C lb2p -P ch1 -t 100000
pi        1231  2.8  0.5  13604  5224 ?        SL   03:01  21:15 alsaloop -C lb1p -P ch0 -t 100000
pi        1313 24.7  0.5  13652  5388 ?        RL   03:03 185:05 alsaloop -C lb2p -P ch1 -t 100000
```strong text
15

It looks like your alsa has reached some strange configuration, which is best solved by reflashing. Follow our guide here for how to reflash, but use this image instead

16

Ok the problems are solved for now but still what causes

So that Loopback initialization failure and that playback ch3 open error: No such device

17

well that did not took long now after fresh firmware flash

Dec 15 21:05:05 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:05:04 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:05:03 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:05:02 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:05:01 amplipi CRON[9127]: pam_unix(cron:session): session closed for user pi
Dec 15 21:05:01 amplipi CRON[9128]: (root) CMD ( /opt/support_tunnel/venv/bin/python3 -m invoke -r /opt/support_tunnel connect-approved-tunnels)
Dec 15 21:05:01 amplipi CRON[9129]: (pi) CMD (/home/pi/amplipi-dev/scripts/check-online)
Dec 15 21:05:01 amplipi CRON[9127]: pam_unix(cron:session): session opened for user pi by (uid=0)
Dec 15 21:05:01 amplipi CRON[9126]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 15 21:05:01 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:04:59 amplipi authbind[853]: overrun for capture lb2p
Dec 15 21:04:58 amplipi authbind[853]: INFO: 192.168.1.181:45192 - “GET /api HTTP/1.1” 200 OK
Dec 15 21:04:58 amplipi authbind[853]: overrun for capture lb2p

18

It’s fairly odd to run into this situation repeatedly, especially so quickly. I’ll suggest you open a ticket with support@micro-nova.com so we can provide a better and more detailed support experience

If possible, I’d start that email interaction with a support tunnel which you can start from your system by going to Settings → Admin Panel → Support Tunnel and following the directions there