Intermittent PermissionDenied StatusCode(403) Errors

[ADHDSquir]

Look for similar bugs

None recently and not using the new OAuth in v0.5.0

Description

Playback intermittently fails with the error:
Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Sometimes things are fine for 2+ days before failure and other times failure occurs immediately after launching librespot.

I authenticated using the new OAuth process last week and have exclusively used the cached credentials.json file since then with no need to re-auth.

Version

0.5.0 built from crates.io

How to reproduce

I have not been able to determine a reliable way to reproduce the behavior.
For reference, I am launching librespot with the following:
librespot --cache /authcache --disable-discovery --name "Spotty" --bitrate 320 --backend pipe --verbose

Log

12-18-09.985 [Debug] (librespot_playback::player) command=EmitShuffleChangedEvent(true)
12-18-10.237 [Debug] (librespot_playback::player) command=EmitSessionConnectedEvent("NDgx...QQ%3D%3D", "spusername")
12-18-10.238 [Debug] (librespot_playback::player) command=EmitSessionClientChangedEvent("8f2c...662c", "", "Denon", "DENON-DWAVR_60-S970")
12-18-10.238 [Debug] (librespot_playback::player) command=EmitVolumeChangedEvent(65535)
12-18-10.238 [Debug] (librespot_playback::player) command=EmitAutoPlayChangedEvent(false)
12-18-10.238 [Debug] (librespot_playback::player) command=EmitFilterExplicitContentChangedEvent(false)
12-18-10.238 [Debug] (librespot_playback::player) command=EmitShuffleChangedEvent(true)
12-18-10.238 [Debug] (librespot_playback::player) command=EmitRepeatChangedEvent(false)
12-18-10.271 [Debug] (librespot_playback::player) command=SetAutoNormaliseAsAlbum(false)
12-18-10.271 [Debug] (librespot_playback::player) command=Load(SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz"), true, 0)
12-18-10.272 [Debug] (librespot::component) new SpClient
12-18-10.272 [Info]  (librespot_core::spclient) Resolved "gue1-spclient.spotify.com:443" as spclient access point
12-18-10.272 [Debug] (librespot::component) new TokenProvider
12-18-10.273 [Debug] (librespot_core::spclient) Client token unavailable or expired, requesting new token.
12-18-10.273 [Debug] (librespot_core::http_client) Requesting https://clienttoken.spotify.com/v1/clienttoken
12-18-10.338 [Debug] (librespot_core::spclient) Client token unavailable or expired, requesting new token.
12-18-10.338 [Debug] (librespot_core::http_client) Requesting https://clienttoken.spotify.com/v1/clienttoken
12-18-10.396 [Debug] (librespot_core::spclient) Received a granted token
12-18-10.397 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:artist:3bYcjbVAN3rAuU3TMzw2mB?autoplay=false&product=0&country=US&salt=4030042709
12-18-10.398 [Debug] (librespot_core::spclient) Received a granted token
12-18-10.398 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/203b3a75bdfa44de96ee764d0a5e3f4d?product=0&country=US&salt=814803965
12-18-10.559 [Error] (librespot_playback::player) Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
12-18-10.559 [Error] (librespot_playback::player) Skipping to next track, unable to load track <SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz")>: ()
12-18-10.562 [Error] (librespot_connect::spirc) ContextError: Error { kind: PermissionDenied, error: StatusCode(403) }
12-18-10.563 [Debug] (librespot_connect::spirc) Marked <TrackRef { gid: Some([32, 59, 58, 117, 189, 250, 68, 222, 150, 238, 118, 77, 10, 94, 63, 77]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at 0 as NonPlayable
12-18-10.563 [Debug] (librespot_playback::player) command=Preload(SpotifyId("spotify:track:171xo7JC4bf7vqFmjF88M8"))
12-18-10.563 [Debug] (librespot_playback::player) Preloading track
12-18-10.564 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/2494640838e34f8691ea0b006b4580b8?product=0&country=US&salt=782394283
12-18-10.644 [Error] (librespot_playback::player) Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
12-18-10.644 [Debug] (librespot_playback::player) Unable to preload SpotifyId("spotify:track:171xo7JC4bf7vqFmjF88M8")

Host (what you are running librespot on):

• OS: Debian Linux
• Platform: Docker on Pi 4

Additional context

[kingosticks]

And if you retry the same file it works?

[ADHDSquir]

Correct. Without making any changes to my setup, the same track now plays:

13-29-16.992 [Debug] (librespot_playback::player) command=SetAutoNormaliseAsAlbum(false)
13-29-16.997 [Debug] (librespot_playback::player) command=Load(SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz"), true, 0)
13-29-16.998 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/203b3a75bdfa44de96ee764d0a5e3f4d?product=0&country=US&salt=377377613
13-29-17.031 [Error] (librespot_connect::spirc) ContextError: Error { kind: NotFound, error: StatusCode(404) }
13-29-17.110 [Info]  (librespot_playback::player) Loading <Fare Thee Well (Dink's Song)> with Spotify URI <spotify:track:0YOOXnCJihgyluizqhAcrz>
13-29-17.110 [Debug] (librespot_audio::fetch) Downloading file 845d...35d8
13-29-17.111 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/storage-resolve/files/audio/interactive/845d...35d8?product=0&country=US&salt=4042318107
13-29-17.592 [Info]  (librespot_playback::player) <Fare Thee Well (Dink's Song)> (180400 ms) loaded
13-29-17.592 [Info]  (LibrespotStream) metadata: <Fare Thee Well (Dink's Song)>
13-29-18.221 [Debug] (librespot_audio::fetch) Downloading file 845d...35d8 complete
13-29-18.250 [Debug] (librespot_audio::fetch) File 845d...35d8 cached to "/authcache/files/84/5dd1...35d8"

[kingosticks]

Sorry, trying to understand, do you have to restart librespot to get it working again or is it the same session? If you don't restart librespot, does everything fail after this or is it still intermittent?

[kingosticks]

Also, are you able to try the latest code rather than the 0.5.0 release? This part of the code has changed.

[ADHDSquir]

No restart of anything involved. If I wait a bit and try the exact same uri again, it will eventually start working again.

I'm running the 0.5.0 from crates.io but I can try to compile the dev branch and see if that makes a difference. I didn't see any commits that I thought would affect this issue so I hadn't tried a dev branch build.

[kingosticks]

Perhaps it's working again once the access token expires and we get a new one. Can you see that happening in your debug log?

4580dab is a different method to obtain access tokens, it's likely relevent.

[ADHDSquir]

Ah, I took that to mean that the login5 process was changed and wouldn't affect my OAuth process, didn't look/understand close enough. I'm compiling the dev version now and will try that out.

Here are complete logs from the past hour where the command Load(SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz"), true, 0) fails at 08-58-44 and then the exact same command succeeds at 09-40-07 with no mention of refreshing a token or anything. Interestingly, the log in my original message includes this exact same Load track uri followed by two token refreshes and then an immediate 403 failure which seems to suggest it's not failing for lack of a fresh token.

08-58-44.087 [Debug] (librespot_playback::player) command=Load(SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz"), true, 0)
08-58-44.087 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:artist:3bYcjbVAN3rAuU3TMzw2mB?autoplay=false&product=0&country=US&salt=2932143837
08-58-44.087 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/203b3a75bdfa44de96ee764d0a5e3f4d?product=0&country=US&salt=1528491360
08-58-44.087 [Error] (librespot_connect::spirc) ContextError: Error { kind: PermissionDenied, error: StatusCode(403) }
08-58-44.088 [Error] (librespot_playback::player) Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
08-58-44.089 [Error] (librespot_playback::player) Skipping to next track, unable to load track <SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz")>: ()
08-58-44.089 [Debug] (librespot_connect::spirc) Marked <TrackRef { gid: Some([32, 59, 58, 117, 189, 250, 68, 222, 150, 238, 118, 77, 10, 94, 63, 77]), uri: None, queued: None, context: Some("NonPlayable"), special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }> at 0 as NonPlayable
08-58-44.089 [Debug] (librespot_playback::player) command=Preload(SpotifyId("spotify:track:171xo7JC4bf7vqFmjF88M8"))
08-58-44.089 [Debug] (librespot_playback::player) Preloading track
08-58-44.090 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/2494640838e34f8691ea0b006b4580b8?product=0&country=US&salt=749204984
08-58-44.170 [Error] (librespot_playback::player) Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
08-58-44.171 [Debug] (librespot_playback::player) Unable to preload SpotifyId("spotify:track:171xo7JC4bf7vqFmjF88M8")
09-40-07.873 [Debug] (librespot_playback::player) command=SetAutoNormaliseAsAlbum(false)
09-40-07.873 [Debug] (librespot_playback::player) command=Load(SpotifyId("spotify:track:0YOOXnCJihgyluizqhAcrz"), true, 0)
09-40-07.874 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/radio-apollo/v3/tracks/spotify:artist:3bYcjbVAN3rAuU3TMzw2mB?autoplay=false&product=0&country=US&salt=1547478466
09-40-07.894 [Debug] (librespot_core::http_client) Requesting https://gue1-spclient.spotify.com:443/metadata/4/track/203b3a75bdfa44de96ee764d0a5e3f4d?product=0&country=US&salt=4067724517
09-40-08.013 [Info]  (librespot_playback::player) Loading <Fare Thee Well (Dink's Song)> with Spotify URI <spotify:track:0YOOXnCJihgyluizqhAcrz>
09-40-08.013 [Debug] (librespot_audio::fetch) File 845dd157bcdd3f63c7de0bc9f2754f96f63c35d8 already in cache
09-40-08.030 [Info]  (librespot_playback::player) <Fare Thee Well (Dink's Song)> (180400 ms) loaded
09-40-08.030 [Info]  (LibrespotStream) metadata: <Fare Thee Well (Dink's Song)>
09-40-08.280 [Info]  (librespot_connect::spirc) Resolved 50 tracks from <"spotify:artist:3bYcjbVAN3rAuU3TMzw2mB">

[roderickvd]

I'm on mobile so not ideal to read through the logs. Am I right that:

• the track seems to be coming from a "NonPlayable" context?

• first time when it fails, the metadata query returns a 403?

• second time when it succeeds, the metadata query now returns a 404?

[kingosticks]

the track seems to be coming from a "NonPlayable" context?

I think that's just librespot marking it like that in response to the failure (// Misuse context field to flag the track).

What's happened to the trace logging ? Can you please provide the full --verbose logs?

[ADHDSquir]

These are the logs I got even with - -verbose. I think that's because of the way I'm getting the logs from the Docker container.

But, good news, after compiling the dev branch on Friday and running that build for the last couple of days, I haven't had any auth issues.

[roderickvd]

Cool. Gonna consider this as fixed then! Feel free to reopen when it reoccurs.