Playback stops after a few hours

[musshorn]

Describe the bug
After around 3 hours of playback, it just stops completely and every song becomes unplayable. Looking at the logs there seems to be a lot of 403 errors appearing.

To reproduce
Steps to reproduce the behavior:

1. Listen to any playlist (in AU if that matters?) for around 3 hours.
2. Playback eventually stops mid song usually. Logs show a pattern of increasing failures as it attempts to find a playable song?

Log
A full log so we may trace your problem (launch librespot with --verbose). Format the log as code.
This is the section leading up to the failures. Full log is 1.3mb of mostly working completely fine so I don't know if you want all that.

Jan 16 21:41:47 TVPie librespot[25859]: [2023-01-16T10:41:47Z TRACE librespot_audio::fetch::receive] Time to first byte now estimated as: 25 ms
Jan 16 21:41:48 TVPie librespot[25859]: [2023-01-16T10:41:48Z DEBUG librespot_audio::fetch] Downloading file 3a9dc93876c3685428dd4059e145b5fb664aaed9 complete
Jan 16 21:43:16 TVPie librespot[25859]: [2023-01-16T10:43:16Z DEBUG librespot_core::session] Session strong=4 weak=6
Jan 16 21:45:16 TVPie librespot[25859]: [2023-01-16T10:45:16Z DEBUG librespot_core::session] Session strong=4 weak=6
Jan 16 21:45:28 TVPie librespot[25859]: [2023-01-16T10:45:28Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5HaTv6nHDSVO1LqjwoP7RA"))
Jan 16 21:45:28 TVPie librespot[25859]: [2023-01-16T10:45:28Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:28 TVPie librespot[25859]: [2023-01-16T10:45:28Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z TRACE librespot_core::token] Got token: Token {
Jan 16 21:45:29 TVPie librespot[25859]:         access_token: "BQAW3vhQ3DxzqBa_7GBb9R8i2bD4lfDzqKtqfZYQSxpENw_tHu4e9__LJwme44WKVhz3PSkcVPVpKsS350YVz_-wMItrhaNR3arCtQUHt6Q6DjpncY3MUz5sFxF94yu-QVytkgY7WAMYdoVe6kEnGNQAfhtjO4COOWNgt21Lu8WwR4QcvbotD2jYOLFr_XwrRAu2L2osqML4qNxh1OEiVB2h6Qp97C_tH7wuUzVfCUxFWjOslwKc3ybo",
Jan 16 21:45:29 TVPie librespot[25859]:         expires_in: 3600s,
Jan 16 21:45:29 TVPie librespot[25859]:         token_type: "Bearer",
Jan 16 21:45:29 TVPie librespot[25859]:         scopes: [
Jan 16 21:45:29 TVPie librespot[25859]:             "playlist-read",
Jan 16 21:45:29 TVPie librespot[25859]:         ],
Jan 16 21:45:29 TVPie librespot[25859]:         timestamp: Instant {
Jan 16 21:45:29 TVPie librespot[25859]:             tv_sec: 3133857,
Jan 16 21:45:29 TVPie librespot[25859]:             tv_nsec: 77376107,
Jan 16 21:45:29 TVPie librespot[25859]:         },
Jan 16 21:45:29 TVPie librespot[25859]:     }
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/bb2a4c2d44704cf988d59c7fdb599fbe?product=0&country=AU&salt=3459012271
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:5HaTv6nHDSVO1LqjwoP7RA")
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_connect::spirc] Marked <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at 55 as NonPlayable
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:7Hfo9BnlLIbexptrBjd1Ok"))
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z TRACE librespot_core::token] Got token: Token {
Jan 16 21:45:29 TVPie librespot[25859]:         access_token: "BQDtK6iHUYEaD8paGSBHP10gdKlF_XMw4PoMx9RvJpsXwmfMLjiQ5Vz7TUh87h3PstNdLJb6OVt92uG9ZVPhFrkmYzW89bCFMzla7n3XVg4BlH1r34UbOX048McWgtXTcVpvm7NB4opi0W4UL-wtELIOUoGRegJwcKzO9kUIuQ9Lt7WaCa3vnUIgzCzNz19lQeHjeNCqgMPSb_-3HgJTVqfBJsfPY3LGd3NYCdLqsmL01jUHxLjJO5Ra",
Jan 16 21:45:29 TVPie librespot[25859]:         expires_in: 3600s,
Jan 16 21:45:29 TVPie librespot[25859]:         token_type: "Bearer",
Jan 16 21:45:29 TVPie librespot[25859]:         scopes: [
Jan 16 21:45:29 TVPie librespot[25859]:             "playlist-read",
Jan 16 21:45:29 TVPie librespot[25859]:         ],
Jan 16 21:45:29 TVPie librespot[25859]:         timestamp: Instant {
Jan 16 21:45:29 TVPie librespot[25859]:             tv_sec: 3133857,
Jan 16 21:45:29 TVPie librespot[25859]:             tv_nsec: 692520595,
Jan 16 21:45:29 TVPie librespot[25859]:         },
Jan 16 21:45:29 TVPie librespot[25859]:     }
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/fcead79bb27342ffb627224fed31599c?product=0&country=AU&salt=825977888
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:7Hfo9BnlLIbexptrBjd1Ok")
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_connect::spirc] Marked <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at 56 as NonPlayable
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z WARN  librespot_connect::spirc] Skipping track <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at position [56] of 73
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:0Bl1Gt8R9kjz7JO7SYAuhe"))
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:29 TVPie librespot[25859]: [2023-01-16T10:45:29Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/13c9b0d9e9c54059934670ca2c43b244?product=0&country=AU&salt=262064874
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:0Bl1Gt8R9kjz7JO7SYAuhe")
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_connect::spirc] Marked <gid: "\023\311\260\331\351\305@Y\223Fp\312,C\262D" context: "NonPlayable"> at 57 as NonPlayable
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at position [56] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\023\311\260\331\351\305@Y\223Fp\312,C\262D" context: "NonPlayable"> at position [57] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:1u12SQ8KNyLns7dMDEMc4F"))
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/30c3a7d122504dac8ea6cc4d050cf5f1?product=0&country=AU&salt=1985544221
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:1u12SQ8KNyLns7dMDEMc4F")
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_connect::spirc] Marked <gid: "0\303\247\321\"PM\254\216\246\314M\005\014\365\361" context: "NonPlayable"> at 58 as NonPlayable
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at position [56] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\023\311\260\331\351\305@Y\223Fp\312,C\262D" context: "NonPlayable"> at position [57] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "0\303\247\321\"PM\254\216\246\314M\005\014\365\361" context: "NonPlayable"> at position [58] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:1YO3q4sYvVsXymksb5aV2S"))
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/4114e7d9a53641b1813ccd5b958c7436?product=0&country=AU&salt=2460408331
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:1YO3q4sYvVsXymksb5aV2S")
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_connect::spirc] Marked <gid: "A\024\347\331\2456A\261\201<\315[\225\214t6" context: "NonPlayable"> at 59 as NonPlayable
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at position [56] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\023\311\260\331\351\305@Y\223Fp\312,C\262D" context: "NonPlayable"> at position [57] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "0\303\247\321\"PM\254\216\246\314M\005\014\365\361" context: "NonPlayable"> at position [58] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "A\024\347\331\2456A\261\201<\315[\225\214t6" context: "NonPlayable"> at position [59] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5nMfIpT4sBRTjrNwhHKZxE"))
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Preloading track
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/b0e2b42e583047649e5d77355537f9ba?product=0&country=AU&salt=535468493
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z ERROR librespot_playback::player] Unable to load audio item: Error { kind: PermissionDenied, error: StatusCode(403) }
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Unable to preload SpotifyId("spotify:track:5nMfIpT4sBRTjrNwhHKZxE")
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_connect::spirc] Marked <gid: "\260\342\264.X0Gd\236]w5U7\371\272" context: "NonPlayable"> at 60 as NonPlayable
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\273*L-DpL\371\210\325\234\177\333Y\237\276" context: "NonPlayable"> at position [55] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\374\352\327\233\262sB\377\266\'\"O\3551Y\234" context: "NonPlayable"> at position [56] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\023\311\260\331\351\305@Y\223Fp\312,C\262D" context: "NonPlayable"> at position [57] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "0\303\247\321\"PM\254\216\246\314M\005\014\365\361" context: "NonPlayable"> at position [58] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "A\024\347\331\2456A\261\201<\315[\225\214t6" context: "NonPlayable"> at position [59] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z WARN  librespot_connect::spirc] Skipping track <gid: "\260\342\264.X0Gd\236]w5U7\371\272" context: "NonPlayable"> at position [60] of 73
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:5VarZFY00sO54HErJ3TPCI"))
Jan 16 21:45:30 TVPie librespot[25859]: [2023-01-16T10:45:30Z DEBUG librespot_playback::player] Preloading track

That pattern of an increasing number of tracks failing continues until it's looped through the whole playlist (I assume that's what the position X of 73 is)

Host (what you are running librespot on):

• OS: [e.g. Linux]
• Platform: [e.g. RPi 3B+]
  librespot 0.5.0-dev 8941495 (Built on 2023-01-13, Build ID: fV1kP56b, Profile: release)
  RPI 4b

[roderickvd]

Is this always around 3 hours (and how much exactly)? Strange because I certainly have had longer-than-3-hour listening sessions and not experienced this before.

From the above I see the token is refreshed twice on almost the same second. This leads me to believe there may be a race condition, getting the two tokens in parallel. This may indeed by the case as preloaded threads run in parallel and don't wait when one or the other is getting the token already.

I don't have time to do it, but anyone inclined may try to fix this in spclient by locking a mutex or maybe a Condvar with timeout may be even better to prevent starvation.

[musshorn]

I'm not sure that it's always around 3 hours? but it's happened a few times and always seems to have issues after an extended period of listening.
How long do the session tokens last for?

[roderickvd]

One hour and we refresh them a little while before that just to be sure.

With a full log or at least start and end you can see the interval how long it lasted for you.