librespot-org / librespot

Open Source Spotify client library
MIT License
4.48k stars 542 forks source link

Music stops abruptly when playing long playlists #1238

Open parashar-gaurav opened 6 months ago

parashar-gaurav commented 6 months ago

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\272Cd\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 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 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 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 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):

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 commented 6 months ago

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).