Music stops abruptly when playing long playlists

[parashar-gaurav]

Describe the bug
When streaming long playlists, after loading few tracks and playing them, the connection to the server gets closed, resulting in stopping the music. Currently I am running librespot version 0.3.1 [librespot 0.3.1 f4be9bb (Built on 2022-01-29, Build ID: NGRFBkfi, Profile: release)]

To reproduce
Steps to reproduce the behavior:

1. Launch librespot as a service which restart when the board boots up, with the parameters: name, verbose
2. Connect with 'iOS' device and select some long playlist
3. Play the playlist, after few tracks the music stops abrubtly while loading the next track.

Log
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_connect::spirc] State: context_uri: "spotify:playlist:2KouzYjMI9IXvSB0eQQwqN" index: 10 position_ms: 903 status: kPlayStatusPlay position_measured_at: 1704215584625 context_description: "" shuffle: false repeat: false playing_from_fallback: true row: 0 playing_track_index: 10 track {gid: "\304\365\354\324\251\377Nx\266\240\334\rj \177"} track {gid:
"\221f\033\262\365\330K5\212\000\016f1\001\264\326"} track {gid: "\271\363\253\334\002TD\233\214sM\301}\013x\201"} track
{gid: "\226B\3322\352\247F\216\223\017\337j\252\347s\222"} track {gid:
"\004\311\342\331X\241L5\202pP\343\002\303\355\272"} track {gid: "\224\363X9SMG\273\211\312\027d\345\3053v"} track
{gid: "\257\347\362\2555bG\367\264>l\246d\372\322\317"} track {gid:
"\212\271\272\245\370\374EM\244A\177\306A\026\342\023"} track {gid:
"\373\324D{\350\254I\241\264\331\030\337\276\372A\330"} track {gid:
"H\221\333F\252\226N\303\235\275%\211\032\315\204\242"} track {gid: "Xn'R\222\303NW\252C\247*\313\362.\216"} track
{gid: "\217dV\335P0E-\241\010W\235\230F`~"} track {gid: "\256$\223\031\236\003D\225\226\264s\301\031[\237v"} track {gid:
"\307\004>\374\235\373J\344\257$\370\347\237P\260\307"} track {gid:
"\334QE\333\341\322C\357\271\343\345(Dp\344\260"} track {gid: "3o\025\327\250\331J\323\235\0321{\r\312\242\245"} track
{gid: "\362\306U.\3530C^\252\036O \243\250\t4"} track {gid: "\216\177\272JPJG\006\272\363iy:\317\314\330"} track {gid:
"\363Mp.e\357F\013\275\374\332;\352I\010\206"} track {gid: ";\371\327EQ\210EN\2024\031aS%\217\311"} track {gid:
"\350\346\241\023\332\035D\351\2371\261 \253\356k\021"} track {gid: "&\236\223\352\230y@\222\224\022\272C*d\2045"}
track {gid: "#\223I\273\351cEf\227\211\202\177\031\342\363C"} track {gid:
"\377\266\334qr<B\236\271\276\025\251\355\364\233\322"} track {gid: "\272!\217\307p]O\026\250.\214\262\375\263\227b"}
track {gid: "\346$"\016\022\267C\235\215\260]\243\226d\3670"} track {gid:
"t\230\331\243\024\302ML\250\003\354^\206\025\223\375"} track {gid: "k@\314;l8K\300\222:\222\361w\004#\324"} track {gid:
"_\375\303\227\270\344N\321\213b\216\006\240x\214\366"} track {gid: "a\233\3727\3439NT\2626\000\271L\324\301\177"}
track {gid: "x9\363[+\352H\240\264\260\330\372\350\rB>"} track {gid:
"h\361\035\364\273[F\372\250\307\335\221\027\300\020\225"} track {gid: "ok\210\255g\340Mo\240\340T^\026'\013\353"}
track {gid: "cQ\271[\311\342B\277\221\362\273#\304\365\220\177"} track {gid:
"\352\335\n\262\327\037H\017\231(\017\346\367%\357&"} track {gid: "\373\217\376\243\352]Gj\223\330\340\324$\002\027k"}
track {gid: "\265\322{U\347cJ\010\211)\271\334\024\036\310Y"} track {gid:
"\251\350\337\275m\262D\271\234\362\274\n!&\227t"}

Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_connect::spirc] Frame has 38 tracks
Jan 02 17:13:04 : [2024-01-02T17:13:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 117544013839616218369958057094371487374, audio_type: Track }, true, 903)
Jan 02 17:13:04 : [2024-01-02T17:13:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:13:04 : [2024-01-02T17:13:04Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:2GRFeGUF99J1Pq204dmjzE
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_audio::fetch] Downloading file 0599d8ebe4a1b1d02e10056df30de4cc66dd7ab0
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_core::channel] new ChannelManager
Jan 02 17:13:04 : [2024-01-02T17:13:04Z DEBUG librespot_core::audio_key] new AudioKeyManager
Jan 02 17:13:05 : [2024-01-02T17:13:05Z INFO librespot_playback::player] (61153 ms) loaded
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::player] == Starting sink ==
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Desired Frames per Buffer: 22050
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] No Desired Period size in range reported by the device.
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Buffer size: 22579
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Desired Period Frame range: 2257 (Buffer size / 10) - 5644 (Buffer size / 4)
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Actual Period Frame range as reported by the device: 7526 - 7527
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Failed to set Buffer and/or Period size, falling back to the device's defaults.
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] You may experience higher than normal CPU usage and/or audio issues.
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Buffer: 60211
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Actual Frames per Period: 7526
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Period Buffer size in bytes: 30104
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_playback::audio_backend::alsa] Period Buffer capacity: 30104
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:13:05 : [2024-01-02T17:13:05Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Jan 02 17:13:07 : [2024-01-02T17:13:07Z DEBUG librespot_audio::fetch] File 0599d8ebe4a1b1d02e10056df30de4cc66dd7ab0 complete, saving to cache
Jan 02 17:13:34 : [2024-01-02T17:13:34Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 190600594904563438194216056684949168254, audio_type: Track })
Jan 02 17:13:34 : [2024-01-02T17:13:34Z DEBUG librespot_playback::player] Preloading track
Jan 02 17:13:34 : [2024-01-02T17:13:34Z INFO librespot_playback::player] Loading <Mary Mary Quite Contrary - Piano Version> with Spotify URI spotify:track:4mzKZzExaQcXDTGX0abx3U
Jan 02 17:13:34 : [2024-01-02T17:13:34Z DEBUG librespot_audio::fetch] Downloading file b3510184b658efbc7d61d9afe2306f8da0945693
Jan 02 17:13:34 : [2024-01-02T17:13:34Z INFO librespot_playback::player] <Mary Mary Quite Contrary - Piano Version> (64210 ms) loaded
Jan 02 17:13:36 : [2024-01-02T17:13:36Z DEBUG librespot_audio::fetch] File b3510184b658efbc7d61d9afe2306f8da0945693 complete, saving to cache
Jan 02 17:14:04 : [2024-01-02T17:14:04Z DEBUG librespot_connect::spirc] At track 12 of 38 <"spotify:playlist:2KouzYjMI9IXvSB0eQQwqN"> update [false]
Jan 02 17:14:04 : [2024-01-02T17:14:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:14:04 : [2024-01-02T17:14:04Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 190600594904563438194216056684949168254, audio_type: Track }, true, 0)
Jan 02 17:14:04 : [2024-01-02T17:14:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:14:04 : [2024-01-02T17:14:04Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Jan 02 17:14:39 : [2024-01-02T17:14:39Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 231475577497300997541626785180495355766, audio_type: Track })
Jan 02 17:14:39 : [2024-01-02T17:14:39Z DEBUG librespot_playback::player] Preloading track
Jan 02 17:14:39 : [2024-01-02T17:14:39Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:5iBnwWLOr2XVSAn3OV9dJk
Jan 02 17:14:39 : [2024-01-02T17:14:39Z DEBUG librespot_audio::fetch] Downloading file 4cc3fd190dc4351c801295624fb4746ffd64a6ba
Jan 02 17:14:39 : [2024-01-02T17:14:39Z INFO librespot_playback::player] (61090 ms) loaded
Jan 02 17:14:41 : [2024-01-02T17:14:41Z DEBUG librespot_audio::fetch] File 4cc3fd190dc4351c801295624fb4746ffd64a6ba complete, saving to cache
Jan 02 17:15:04 : [2024-01-02T17:15:04Z DEBUG librespot_core::session] Session[0] strong=3 weak=4
Jan 02 17:15:08 : [2024-01-02T17:15:08Z DEBUG librespot_connect::spirc] At track 13 of 38 <"spotify:playlist:2KouzYjMI9IXvSB0eQQwqN"> update [false]
Jan 02 17:15:08 : [2024-01-02T17:15:08Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:15:08 : [2024-01-02T17:15:08Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 231475577497300997541626785180495355766, audio_type: Track }, true, 0)
Jan 02 17:15:08 : [2024-01-02T17:15:08Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:15:08 : [2024-01-02T17:15:08Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Jan 02 17:15:40 : [2024-01-02T17:15:40Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 264538417872417718612823399885419098311, audio_type: Track })
Jan 02 17:15:40 : [2024-01-02T17:15:40Z DEBUG librespot_playback::player] Preloading track
Jan 02 17:15:40 : [2024-01-02T17:15:40Z INFO librespot_playback::player] Loading with Spotify URI spotify:track:63xpDyGv1Bb4PlzeVMDkwf
Jan 02 17:15:40 : [2024-01-02T17:15:40Z DEBUG librespot_audio::fetch] Downloading file 5add1a54546e09fba397b85f9ee9e67ed1247534
Jan 02 17:15:40 : [2024-01-02T17:15:40Z INFO librespot_playback::player] (60530 ms) loaded
Jan 02 17:15:42 : [2024-01-02T17:15:42Z DEBUG librespot_audio::fetch] File 5add1a54546e09fba397b85f9ee9e67ed1247534 complete, saving to cache
Jan 02 17:16:10 : [2024-01-02T17:16:10Z DEBUG librespot_connect::spirc] At track 14 of 38 <"spotify:playlist:2KouzYjMI9IXvSB0eQQwqN"> update [false]
Jan 02 17:16:10 : [2024-01-02T17:16:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:16:10 : [2024-01-02T17:16:10Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 264538417872417718612823399885419098311, audio_type: Track }, true, 0)
Jan 02 17:16:10 : [2024-01-02T17:16:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
Jan 02 17:16:10 : [2024-01-02T17:16:10Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
Jan 02 17:16:28 : [2024-01-02T17:16:28Z WARN librespot_core::session] Connection to server closed.
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::session] Invalidating session[0]
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_playback::player] drop PlayerInternal[0]
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::session] drop Dispatch
Jan 02 17:16:28 : [2024-01-02T17:16:28Z ERROR librespot_connect::spirc] subscription terminated
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_connect::spirc] drop Spirc[0]
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_playback::player] Shutting down player thread ...
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_playback::player] PlayerInternal thread finished.
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::session] drop Session[0]
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::audio_key] drop AudioKeyManager
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::channel] drop ChannelManager
Jan 02 17:16:28 : [2024-01-02T17:16:28Z DEBUG librespot_core::mercury] drop MercuryManager
Jan 02 17:16:28 : [2024-01-02T17:16:28Z WARN librespot] Spirc shut down unexpectedly
Jan 02 17:16:29 : [2024-01-02T17:16:29Z INFO librespot_core::session] Connecting to AP "ap-gue1.spotify.com:4070"`

Host (what you are running librespot on):

• OS: Debian
• Platform: RPi 3B+

Additional context
Here is the output of https://apresolve.spotify.com/ when run on that system:

{"ap_list":["ap-gue1.spotify.com:4070","ap-gue1.spotify.com:443","ap-gue1.spotify.com:80","ap-gew4.spotify.com:4070","ap-gae2.spotify.com:443","ap-guc3.spotify.com:80"]}
Any help will be really appreciated.

[roderickvd]

That's a pretty old version that we no longer support. Please update to the latest 0.4.x (release) or 0.5.x (dev).