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…

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.