search

librespot-org / librespot

Open Source Spotify client library
MIT License
4.74k stars 584 forks source link

Suddenly unable to play any tracks #972

Closed kosimst closed 2 years ago

kosimst commented 2 years ago

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:

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.com-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
mchccc commented 2 years ago

Well as a workaround I just tried to use my Spotify creds and that worked without a hitch.

What if I just have a Facebook login? 🥲

Foxtrod89 commented 1 year ago 
This backend is known to panic on several platforms.
Consider using some other backend, or better yet, contributing a fix.
Country: "US"
The application panicked (crashed).
Message:  could not find device
Location: /Users/brew/Library/Caches/Homebrew/cargo_cache/registry/src/github.com-1ecc6299db9ec823/librespot-playback-0.2.0/src/audio_backend/portaudio.rs:62

what is workaround? macOS 11.6

roderickvd commented 1 year ago 
This backend is known to panic on several platforms.
Consider using some other backend, or better yet, contributing a fix.
Country: "US"
The application panicked (crashed).
Message:  could not find device
Location: /Users/brew/Library/Caches/Homebrew/cargo_cache/registry/src/github.com-1ecc6299db9ec823/librespot-playback-0.2.0/src/audio_backend/portaudio.rs:62

what is workaround? macOS 11.6

I don't think this is related to the subject of this issue.

But on Mac, just use Rodio instead of PortAudio. I don't know about this Homebrew recipe but Rodio should be the default backend anyway. Or specify --device with whatever PortAudio needs, because that's what it's complaining about.

samflores commented 1 year ago

I've encountered this problem (I think) and don't know if it's better to create a new GH issue.

I installed the "0.5.0-dev" version yesterday and listened to a couple hours until it stopped and nothing I tried worked - changing backend, editing /etc/hosts, running under a vpn, etc.

The content of http://apresolve.spotify.com/ is:

{"ap_list":["ap-gue1.spotify.com:4070","ap-gue1.spotify.com:443","ap-gue1.spotify.com:80","ap-gew1.spotify.com:4070","ap-gae2.spotify.com:443","ap-guc3.spotify.com:80"]}

I'm starting librespot with librespot -u "<elided>" -p "<elided>" --backend pulseaudio --disable-audio-cache --enable-volume-normalisation --initial-volume=100 -v and seeing this in the log when I try to play anything:

[2023-03-22T12:37:44Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-03-22T12:37:44Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-03-22T12:37:45Z TRACE librespot_core::spclient] Got client token: GrantedTokenResponse { token: "<elided>", expires_after_seconds: 1216800, refresh_after_seconds: 1209600, domains: [TokenDomain { domain: "spotify.com", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }, TokenDomain { domain: "spotify.net", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }], special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }
[2023-03-22T12:37:45Z DEBUG librespot_core::http_client] Requesting https://gue1-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:playlist:2UZNfy8WUroWSoirsnHtom?autoplay=false&product=0&country=BR&salt=1654385305
[2023-03-22T12:37:45Z TRACE librespot_core::spclient] Got client token: GrantedTokenResponse { token: "<elided>", expires_after_seconds: 1216800, refresh_after_seconds: 1209600, domains: [TokenDomain { domain: "spotify.com", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }, TokenDomain { domain: "spotify.net", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }], special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }
[2023-03-22T12:37:45Z DEBUG librespot_core::http_client] Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/a1df9480c2bd4ffd9ea91ca2dee3e992?product=0&country=BR&salt=2730999404
[2023-03-22T12:37:45Z ERROR librespot_connect::spirc] ContextError: Error { kind: PermissionDenied, error: StatusCode(403) }
[2023-03-22T12:37:45Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-03-22T12:37:45Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-03-22T12:37:45Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
[2023-03-22T12:37:45Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId("spotify:track:4VrWlk8IQxevMvERoX08iC")>: ()
[2023-03-22T12:37:45Z DEBUG librespot_connect::spirc] Marked <TrackRef { gid: Some([161, 223, 148, 128, 194, 189, 79, 253, 158, 169, 28, 162, 222, 227, 233, 146]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at 0 as NonPlayable
[2023-03-22T12:37:45Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:1zeH4lyTUZBp567d6K6zTM"))
[2023-03-22T12:37:45Z DEBUG librespot_playback::player] Preloading track
[2023-03-22T12:37:45Z DEBUG librespot_core::http_client] Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/3387daeed88e4ffc87a270defff49ebe?product=0&country=BR&salt=66342655
[2023-03-22T12:37:46Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
[2023-03-22T12:37:46Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:1zeH4lyTUZBp567d6K6zTM")
roderickvd commented 1 year ago

Weird. Have you tried blacklisting ap-gue1.spotify.com in /etc/hosts? See if another access point will work?

samflores commented 1 year ago

If I point it to 0.0.0.0 librespot just closes and in the log I get:

[2023-03-22T13:18:45Z INFO  librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"
[2023-03-22T13:18:45Z DEBUG librespot_playback::player] Shutting down player thread ...
[2023-03-22T13:18:45Z DEBUG librespot_playback::player] drop PlayerInternal[0]
[2023-03-22T13:18:45Z DEBUG librespot_playback::player] PlayerInternal thread finished.
[2023-03-22T13:18:45Z ERROR librespot] could not initialize spirc: Service unavailable { Connection refused (os error 111) }

If I block apresolve.spotify.com, though, I see this:

[2023-03-22T13:22:09Z WARN  librespot_core::apresolve] Failed to resolve all access points, using fallbacks
[2023-03-22T13:22:09Z WARN  librespot_core::apresolve] Resolve access points error: Service unavailable { error trying to connect: tcp connect error: Connection refused (os error 111) }
[2023-03-22T13:22:09Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"

but when I try to play anything I get the same error, with a different URL:

[2023-03-22T13:23:09Z DEBUG librespot_core::http_client] Requesting https://spclient.wg.spotify.com:443/metadata/4/track/e666c6ccc4c7437f83552aa9bf4f2cfd?product=0&country=BR&salt=3571593297
[2023-03-22T13:23:09Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
[2023-03-22T13:23:09Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:70LcF31zb1H0PyJoS1Sx1r")
smilg commented 1 year ago

FWIW I'm having the same issue, though I'm unable to modify /etc/hosts due to some details of my setup. Did you happen to find a fix?

bjorgvino commented 2 weeks ago

I ran into this on a Raspberry Pi running raspotify. I've been able to use it to play music from Spotify without problems, but all of the sudden I started getting this error when trying to play tracks - and tracks just skipped ahead immediately all the time:

Aug 30 12:56:08 Grottan librespot[558]: [2024-08-30T10:56:08Z ERROR librespot_core::channel] channel error: 2 0
Aug 30 12:56:08 Grottan librespot[558]: [2024-08-30T10:56:08Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
Aug 30 12:56:08 Grottan librespot[558]: [2024-08-30T10:56:08Z ERROR librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 293957129610060129689800402008964857369, audio_type: Track }>: ()
Aug 30 12:56:08 Grottan librespot[558]: [2024-08-30T10:56:08Z ERROR librespot_core::channel] channel error: 2 0
Aug 30 12:56:08 Grottan librespot[558]: [2024-08-30T10:56:08Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError

The output of http://apresolve.spotify.com/ for me is:

{"ap_list":["ap2-gew4.spotify.com:4070","ap2-gew4.spotify.com:443","ap2-gew4.spotify.com:80","ap2-guc3.spotify.com:4070","ap2-gue1.spotify.com:443","ap2-gew1.spotify.com:80"]}

If I block apresolve.spotify.com, i.e. add the following to /etc/hosts: 0.0.0.0 apresolve.spotify.com, raspotify on my Raspberry Pi starts working again because it falls back to ap.spotify.com:443:

Aug 30 13:29:01 Grottan librespot[2870]: [2024-08-30T11:29:01Z INFO  librespot] librespot 0.4.2 a6e1258 (Built on 2023-06-21, Build ID: g9ifMDjd, Profile: release)
Aug 30 13:29:15 Grottan librespot[2870]: [2024-08-30T11:29:15Z WARN  librespot_core::apresolve] Failed to resolve Access Point: error trying to connect: tcp connect error: Connection refused (os error 111)
Aug 30 13:29:15 Grottan librespot[2870]: [2024-08-30T11:29:15Z WARN  librespot_core::apresolve] Using fallback "ap.spotify.com:443"
Aug 30 13:29:15 Grottan librespot[2870]: [2024-08-30T11:29:15Z INFO  librespot_core::session] Connecting to AP "ap.spotify.com:443"

Yay!

mrkickling commented 2 weeks ago

Had the same problem, can verify that @bjorgvino solution worked. Thanks!

EDIT: Stopped working sep 4th

MitraMai commented 2 weeks ago

@bjorgvino 's solution worked for me! Many thanks!

web-sash commented 2 weeks ago

@bjorgvino 's solution worked for me also! Thanks a lot..

The fix stoppped working today 04. September. ap.spotify.com doesn't seem to be reachable anymore

kingosticks commented 2 weeks ago

Are you all using zeroconf to authenticate ?

kingosticks commented 2 weeks ago

I can answer my own question: no, it's not directly due to authentication method. Please correct me if I am wrong, but it's presumably because you're all using v0.4.x. This problem doesn't exist for me in the dev branch, but does in the master branch.

bjorgvino commented 2 weeks ago

Yeah I'm using the latest release, 0.4.2.

No authentication. It's just that the first access point doesn't seem to work for me (and others it seems), perhaps because of the port, or something completely different, and the fallback logic doesn't seem to kick in... i.e. it doesn't try the other access points.

Btw what I posted was not in any way "my solution", I just tried stuff already suggested in this thread and reported back how it went..

kingosticks commented 2 weeks ago

It would only try the other access points it connecting fails. In the cases here, connection and authentication are seemingly work fine, it's the subsequent requesting of audio data that fails when using certain access points.

I appreciate not your solution, I was just trying to work out if further investigation was required. But given this all works in the latest code (that obtains audio data a different way), the answer is no.

bjorgvino commented 2 weeks ago

Understood. Perhaps a new release is in order then?

truppelito commented 2 weeks ago

Blocking apresolve.spotify.com on my AdGuard Home server worked for me too.

bestlibre commented 1 week ago

It worked for me until this morning. I'm getting the same error with the ap.spotify.com fallback

kingosticks commented 1 week ago

Then you'll have to switch to the real fix. which is to compile using the dev branch.

mloskot commented 1 week ago

https://github.com/librespot-org/librespot/issues/972#issuecomment-2320943137 workaround does not work for me:

$ cat /etc/hosts
127.0.0.1 localhost
127.0.1.1 s4ap
# spotify_player workaround, see https://github.com/librespot-org/librespot/issues/972#issuecomment-2320943137
0.0.0.0 apresolve.spotify.com
...

restart spotify_player and it keeps skipping as I show in

jaypi95 commented 1 week ago

Then you'll have to switch to the real fix. which is to compile using the dev branch.

I did this two days ago because of the zeroconf thing but as of this morning it stopped working again. Overriding the DNS entry also didn't work this time.

But blocking apresolve.spotify.com did the trick!