Suddenly unable to play any tracks

[kosimst]

I am using LibreSpot with the JACK Audio backend, and it worked perfectly, but since a few days I can't play any tracks. I didn't change any configurations on my side, so I assume there is a problem with spotify like it already occured here: #510

Setup

Custom compiled with --no-default-features and --features jackaudio-backend running as a user service on a Raspberry Pi.

Used Arguments:

• backend: jackaudio
• bitrate: 320
• no-audio-cache & no-credential-cache

LibreSpot allows connections from any device just fine, but can't play any song, no matter of its length. Mots of the time it just skips every song after a few seconds without any audio played, but sometimes it also crashes completely.

Logs:

Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_core::channel] channel error: 2 1
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z INFO  librespot_playback::player] Loading <Lightning Over Heaven> with Spotify URI <spotify:track:0S0zgiheqNBkRjEMo7pnig>
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 38045326986839703698416089418933192304, audio_type: Track }>: ()
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z INFO  librespot_playback::player] Loading <Lightning Over Heaven> with Spotify URI <spotify:track:0S0zgiheqNBkRjEMo7pnig>
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_core::channel] channel error: 2 1
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 38045326986839703698416089418933192304, audio_type: Track }>: ()
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_core::channel] channel error: 2 1
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z INFO  librespot_playback::player] Loading <Lightning Over Heaven> with Spotify URI <spotify:track:0S0zgiheqNBkRjEMo7pnig>
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_core::channel] channel error: 2 1
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_core::channel] channel error: 2 1
Mar 02 10:48:40 raspberrypi librespot[714]: [2022-03-02T15:48:40Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Mar 02 10:48:40 raspberrypi librespot[714]: thread '<unnamed>' panicked at 'Map must not be polled after it returned `Poll::Ready`', /home/pi/.cargo/registry/src/github.jpy.wang-1285ae84e5963aae/futures-util-0.3.17/src/future/future/map.rs:62:17
Mar 02 10:48:40 raspberrypi librespot[714]: stack backtrace:
Mar 02 10:48:41 raspberrypi librespot[714]:    0:   0x8febfc - std::backtrace_rs::backtrace::libunwind::trace::h532c701585cd392d
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
Mar 02 10:48:41 raspberrypi librespot[714]:    1:   0x8febfc - std::backtrace_rs::backtrace::trace_unsynchronized::h15e96deae50ea7f1
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
Mar 02 10:48:41 raspberrypi librespot[714]:    2:   0x8febfc - std::sys_common::backtrace::_print_fmt::h2de65accbd58b3e4
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/sys_common/backtrace.rs:67:5
Mar 02 10:48:41 raspberrypi librespot[714]:    3:   0x8febfc - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h85671ae76efc2464
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/sys_common/backtrace.rs:46:22
Mar 02 10:48:41 raspberrypi librespot[714]:    5:   0x8f709c - std::io::Write::write_fmt::hcccb69ae7e0e5712
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/io/mod.rs:1697:15
Mar 02 10:48:41 raspberrypi librespot[714]:    6:   0x900c68 - std::sys_common::backtrace::_print::hedd1975fac8ef971
panicking.rs:211:50pberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/sys_common/backtrace.rs:49:5
Mar 02 10:48:41 raspberrypi librespot[714]:    9:   0x900710 - std::panicking::default_hook::h76fa136e1f70a214
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/std/src/panicking.rs:228:9
Mar 02 10:48:41 raspberrypi librespot[714]:   14:   0x61fd54 - <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll::h6cdb6d970c4ac361
Mar 02 10:48:41 raspberrypi librespot[714]:   15:   0x60d7d8 - <futures_util::future::try_future::MapErr<Fut,F> as core::future::future::Future>::poll::hfe2e84411f277e84
Mar 02 10:48:41 raspberrypi librespot[714]:   16:   0x5fbd10 - <librespot_playback::player::PlayerInternal as core::future::future::Future>::poll::h28a4cde177e46443
Mar 02 10:48:41 raspberrypi librespot[714]:   17:   0x4c7774 - std::thread::local::LocalKey<T>::with::h85f1e7d59454df33
Mar 02 10:48:41 raspberrypi librespot[714]:   18:   0x4bbad4 - futures_executor::local_pool::block_on::hefeadbfdb9a235f9
Mar 02 10:48:41 raspberrypi librespot[714]:   19:   0x567ff4 - std::sys_common::backtrace::__rust_begin_short_backtrace::ha9233c878f46eaea
Mar 02 10:48:41 raspberrypi librespot[714]:   20:   0x5287ac - core::ops::function::FnOnce::call_once{{vtable.shim}}::he863134c8af815b9
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/alloc/src/boxed.rs:1694:9
Mar 02 10:48:41 raspberrypi librespot[714]:   22:   0x9061e4 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h3a9e9491476f36e5
Mar 02 10:48:41 raspberrypi librespot[714]:                        at /rustc/db9d1b20bba1968c1ec1fc49616d4742c1725b4b/library/alloc/src/boxed.rs:1694:9
Mar 02 10:48:41 raspberrypi librespot[714]: [2022-03-02T15:48:41Z ERROR librespot_playback::player] Player Commands Error: channel closed
Mar 02 10:48:41 raspberrypi librespot[714]: [2022-03-02T15:48:41Z ERROR librespot_playback::player] Player Commands Error: channel closed
Mar 02 10:48:41 raspberrypi librespot[714]: [2022-03-02T15:48:41Z ERROR librespot_playback::player] Player Commands Error: channel closed
Mar 02 10:48:42 raspberrypi librespot[714]: [2022-03-02T15:48:42Z ERROR librespot_playback::player] Player Commands Error: channel closed

[michaelherger]

Where about on this planet are you located? I've received a few similar reports from users in the past few days.

[cvejlbo]

Just in case you are gathering stats/data:
Same issue for me (in Denmark).

[jesperll]

Same here (via Spotty integration in Logitech Media Server) (also Denmark)

[michaelherger]

@jesperll - you're not JesperDB who's been reporting this similar issue to me, are you?

That then would be three Danish users. It's hard to believe this was a coincidence...

[kosimst]

I am from Austria @michaelherger, so maybe the problem is in europe.

[ashthespy]

Also saw similar channel errors from DK..

[JesperBarrit]

@jesperll - you're not JesperDB who's been reporting this similar issue to me, are you?

No, that's me and I'm also in Denmark :)

I have the same issue here:
https://forums.slimdevices.com/showthread.php?111923-Announce-Spotty-4-0-integrate-local-library-with-your-Spotify-collection-(LMS-8-)&p=1049289&viewfull=1#post1049289

[cvejlbo]

FWIW: A similar issue seem to happen if I try using new-api branch, except the spotify client/UI on my PC/phone does not repeatedly skip fwd after ~5 secs [still no playback, though]

Console log with -v from new-api branch:

[...]
[2022-03-03T10:43:35Z TRACE librespot_connect::spirc] Frame has 48 tracks
[2022-03-03T10:43:35Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
[2022-03-03T10:43:35Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2C0iEdLXanscPYGpwO2oSm"), true, 115962)
[2022-03-03T10:43:35Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2022-03-03T10:43:35Z DEBUG librespot::component] new SpClient
[2022-03-03T10:43:35Z INFO  librespot_core::spclient] Resolved "gew1-spclient.spotify.com:443" as spclient access point
[2022-03-03T10:43:35Z DEBUG librespot::component] new TokenProvider
[2022-03-03T10:43:35Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
[2022-03-03T10:43:35Z TRACE librespot_connect::spirc] ==> kPlayStatusLoading
[2022-03-03T10:43:35Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusLoading]
[2022-03-03T10:43:35Z ERROR librespot_core::mercury] error 403 for uri hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae
[2022-03-03T10:43:35Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: Unavailable, error: Response(MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] }) }
[2022-03-03T10:43:35Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:2C0iEdLXanscPYGpwO2oSm")>: ()
[2022-03-03T10:43:35Z ERROR librespot_core::session] could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] } }
[2022-03-03T10:43:35Z DEBUG librespot_connect::spirc] Marked <gid: "U\332\267\0046uOl\202YV\344\261\037\241\332" context: "NonPlayable"> at 1 as NonPlayable
[2022-03-03T10:43:35Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:40NRy5xeT32HCLae48DVov"))
[2022-03-03T10:43:35Z DEBUG librespot_playback::player] Preloading track
[2022-03-03T10:43:35Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
[2022-03-03T10:43:36Z ERROR librespot_core::mercury] error 403 for uri hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae
[2022-03-03T10:43:36Z ERROR librespot_core::session] could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] } }
[2022-03-03T10:43:36Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: Unavailable, error: Response(MercuryResponse { uri: "hm://keymaster/token/authenticated?scope=playlist-read&client_id=65b708073fc0480ea92a077233ca87bd&device_id=ce8d71004f9597141d4b5940bd1bb2dc52a35dae", status_code: 403, payload: [[123, 34, 99, 111, 100, 101, 34, 58, 52, 44, 34, 101, 114, 114, 111, 114, 68, 101, 115, 99, 114, 105, 112, 116, 105, 111, 110, 34, 58, 34, 73, 110, 118, 97, 108, 105, 100, 32, 114, 101, 113, 117, 101, 115, 116, 34, 125]] }) }
[2022-03-03T10:43:36Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:40NRy5xeT32HCLae48DVov")
[...]

However, if I start librespot with -u <username> -p <password> with same build from new-api branch, I am able to play back the audio.
Maybe there were some recent changes to how the authentication is done with zeroconf?

[roderickvd]

Put simply, we can't do anything about channel errors. They sometimes hit the Spotify infrastructure and then go away after some time.

The panic is due to trying to reload a track that couldn't be loaded the first time. This is fixed in new-api meaning that it won't panic anymore, but still won't be able to play the track.

There is no difference in authentication to the Spotify infrastructure between zeroconf and command line, all that matters is the way it receives the credentials (either from the command line or over the LAN). From there it authenticates against Spotify in the same way.

It's more likely that the time you logged in with command line credentials, you connected to an access point that didn't suffer from channel errors. You can check the access point in your (verbose) logs when librespot first connects.

I'm closing this as this is not something we can do anything about.

[kingosticks]

I do agree in general. But we could in theory provide an API to control what access point is used rather than always taking the first (or last, whatever it is, I find the comment there confusing). I am not saying that should then also be exposed to librespot application users (yet another program option) but it could.

[morphar]

Just sharing info, in case it's helpful:
In DK.
2 official spotify clients working (1 not updated macOS, 1 latest releas iOS).
They play just fine, except for trying to use Spotify Connect, with anything derived from or using librespot to enable Spotify Connect (E.g. Volumio 3 and spotifyd).
Problem: Causes all tracks to skip.

[puerto-rico]

i am seeing same thing here. also in denmark. skips all tracks in playlist - happend on 2 pi's at the same time.
but because there where running a older version of dietpi i upgrade to bulseye and installed from scratch. with no luck.

All tracks get skipped and from journalctl -f i can see the error.

[michaelherger]

Would everybody mind sharing

• what ISP you're using
• the result of http://apresolve.spotify.com/

Though there have been reports from Germany and Austria, too, I strongly believe this is either a geographical thing, or some network having issues or blocking things.