Snapserver + Librespot stop working after ~1-2 hours, requiring a restart

[roldengarm]

Description

I'm runing Snapserver + Librespot. It was working fine until a week or so ago, when I enabled Music Assistant. I've now disabled Music Assistant, but the problem exists.
It works fine for 1-2 hours, but then I can no longer play music from an Android Spotify client. Snapserver shows up, but it disconnects immediately

Version

The latest version from git

Log

Below logs from Snapserver at the time the problem happens.

Apr 12 14:48:45 server snapserver[2638934]: (librespot_core::dealer) No subscriber for msg.uri: social-connect/v2/broadcast_status_update
Apr 12 14:48:48 server snapserver[2638934]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 12 14:48:49 server snapserver[2638934]: (librespot_connect::spirc) device became inactive
Apr 12 14:48:49 server snapserver[2638934]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 12 14:48:49 server snapserver[2638934]: (librespot_core::dealer) No subscriber for msg.uri: social-connect/v2/broadcast_status_update
Apr 12 14:48:49 server snapserver[2638934]: (librespot_playback::player) Loading <Supergirl> with Spotify URI <spotify:track:0d8OzTCvIWtNrZLflzHed0>
Apr 12 14:48:49 server snapserver[2638934]: (librespot_connect::spirc) failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
Apr 12 14:48:49 server snapserver[2638934]: (librespot_connect::spirc) session update: <Ok(NEW_SESSION)> for self, current session_id c2cbe6bf21814d45ab03623a1e6f47d1, new session_id 06778907fbf2878b464676327a002009
Apr 12 14:48:49 server snapserver[2638934]: (librespot_connect::spirc) could not parse session_update: Invalid state { Unknown enum variant name: `WIFI_BROADCAST_CHANGED` at 1:11 }
Apr 12 14:48:50 server snapserver[2638934]: (librespot_playback::player) <Supergirl> (197189 ms) loaded
Apr 12 14:48:50 server snapserver[2638934]: (LibrespotStream) metadata: <Supergirl>
Apr 12 14:48:50 server snapserver[2638934]: (ControlServer) Removing 2 inactive session(s), active sessions: 1

After a restart, with the same song, the logs are:

Apr 12 15:01:56 server snapserver[2755620]: (librespot_core::session) Connecting to AP "ap-gae2.spotify.com:4070"
Apr 12 15:01:56 server snapserver[2755620]: (librespot_core::session) Authenticated as 'USERID' !
Apr 12 15:01:56 server snapserver[2755620]: (librespot_core::session) Country: "NZ"
Apr 12 15:01:57 server snapserver[2755620]: (librespot_core::spclient) Resolved "gae2-spclient.spotify.com:443" as spclient access point
Apr 12 15:01:57 server snapserver[2755620]: (librespot_connect::spirc) ContextError: Error { kind: NotFound, error: StatusCode(404) }
Apr 12 15:01:57 server snapserver[2755620]: (librespot_playback::player) Loading <Supergirl> with Spotify URI <spotify:track:0d8OzTCvIWtNrZLflzHed0>
Apr 12 15:01:58 server snapserver[2755620]: (librespot_playback::player) Invalid start position of 316354 ms exceeds track's duration of 197189 ms, starting track from the beginning
Apr 12 15:01:58 server snapserver[2755620]: (librespot_playback::player) <Supergirl> (197189 ms) loaded
Apr 12 15:01:58 server snapserver[2755620]: (LibrespotStream) metadata: <Supergirl>
Apr 12 15:01:58 server snapserver[2755620]: (PcmStream) State changed: HomeMusic, state: idle => playing
Apr 12 15:01:58 server snapserver[2755620]: (Server) onStateChanged (HomeMusic): playing
Apr 12 15:02:05 server snapserver[2755620]: (AsioStream) No data since 120 ms, switching to idle
Apr 12 15:02:05 server snapserver[2755620]: (PcmStream) State changed: HomeMusic, state: playing => idle
Apr 12 15:02:05 server snapserver[2755620]: (Server) onStateChanged (HomeMusic): idle

So, it seems that when it fails, it does not authenticate anymore? As there are no authentication logs in the first one.

Host (what you are running librespot on):

• OS: Linux
• Platform: HP 600

[kingosticks]

Can you please fill out the issue template more fully.

• full librespot logs, please provide that rather than what you think is useful.
• steps to reproduce, ideally with standalone librespot. We cannot be expected to know/use snapcast to help you.
• By platform we want to know what CPU architecture, at least. The first Google result for HP 600 is a printer.

[photovoltex]

It's also a shame that snapserver seems to remove the log level of each log entry... So a standalone reproducible solution would be ideal, otherwise this might just be an issue from snapserver or spotify changing some internal handling? Did you perhaps change something on your network setup in recent times?

[photovoltex]

Could you also take a look at #1481, some others also seem to have issues when using snapcast (don't know if that is the same, but I would assume so). I don't think this is the same issue, but maybe correlated.

[roldengarm]

@kingosticks @photovoltex thank you for the replies, and sorry for not providing sufficient information.

By platform we want to know what CPU architecture, at least. The first Google result for HP 600 is a printer.

It's a HP ProDesk 600 G3

It's hard to reproduce the issue as standalone, as it happens after hours / overnight. If really required, I can do another test, but for now I've reproduced the issue with librespot running from snapserver. See logs below.
It worked fine yesterday, then overnight I tried again, and on the first attempt from Spotify it disconnected when selecting the Librespot device from my Android device (around 8:04). However this time the second time it worked, around 8:06.

The one thing I've changed recently on my network is to remove one PiHole DNS server from my network, and upgraded to PiHole v6 on the server that also runs Snapserver + Librespot.

Could you also take a look at #1481, some others also seem to have issues when using snapcast (don't know if that is the same, but I would assume so). I don't think this is the same issue, but maybe correlated.

Yes it's the same product, thanks. Snapcast = snapserver + snapclient, i.e. snapserver runs on one server and snapclient on clients to output audio.
I think it's indeed a different issue.

Apr 14 07:56:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 07:58:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 08:00:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 08:02:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 08:04:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 08:04:29 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) cluster update: Ok(DEVICE_NEW_CONNECTION) from 684310e8b1acf05ac40495c8e1371fdc7d66df06, active device:
Apr 14 08:04:30 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 684310e8b1acf05ac40495c8e1371fdc7d66df06, active device:
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling: 'endpoint: transfer' from 684310e8b1acf05ac40495c8e1371fdc7d66df06
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) found initial track <spotify:track:4Wglx410HPppBEo3oi79k0>
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://login5.spotify.com/v3/login
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_playback::player) command=Load(SpotifyId("spotify:track:4Wglx410HPppBEo3oi79k0"), false, 65626)
Apr 14 08:04:31 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://login5.spotify.com/v3/login
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/a24de0c3c03d4d8692e6e2806dad3da4?product=0&country=NZ&salt=2284944014
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=3177035814
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_playback::player) Loading <Made In The Sky - Artena Remix> with Spotify URI <spotify:track:4Wglx410HPppBEo3oi79k0>
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_audio::fetch) Downloading file d7b4d96d6d6734be3a28b8963797f064375f8a96
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/storage-resolve/files/audio/interactive/d7b4d96d6d6734be3a28b8963797f064375f8a96?product=0&country=NZ&salt=1523506944
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:4M7El604yMVdNJQEY6NfyZ
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 684310e8b1acf05ac40495c8e1371fdc7d66df06, active device:
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) device became inactive
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513/inactive?notify=false&product=0&country=NZ&salt=3419700731
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::dealer::manager) replying to ws request: Success
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::mercury) unknown subscription uri=social-connect/v2/broadcast_status_update
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::session) could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "social-connect/v2/broadcast_status_update", status_code: 200, payload: [[123, 34, 100, 101, 118, 105, 99, 101, 66, 114, 111, 97, 100, 99, 97, 115, 116, 83, 116, 97, 116, 117, 115, 34, 58, 123, 34, 116, 105, 109, 101, 115, 116, 97, 109, 112, 34, 58, 34, 49, 55, 52, 52, 53, 55, 52, 54, 55, 50, 51, 57, 52, 34, 44, 34, 98, 114, 111, 97, 100, 99, 97, 115, 116, 95, 115, 116, 97, 116, 117, 115, 34, 58, 34, 66, 82, 79, 65, 68, 67, 65, 83, 84, 95, 79, 78, 34, 44, 34, 100, 101, 118, 105, 99, 101, 95, 105, 100, 34, 58, 34, 52, 49, 101, 50, 101, 48, 54, 49, 102, 100, 102, 53, 50, 49, 55, 49, 99, 97, 55, 100, 97, 101, 53, 54, 54, 102, 54, 56, 54, 56, 99, 102, 98, 52, 100, 98, 49, 53, 49, 51, 34, 44, 34, 109, 100, 110, 115, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 49, 79, 87, 69, 120, 55, 55, 81, 103, 73, 66, 85, 114, 117, 74, 51, 82, 89, 56, 51, 114, 97, 34, 125, 44, 34, 115, 111, 99, 105, 97, 108, 95, 114, 97, 100, 97, 114, 95, 116, 111, 107, 101, 110, 34, 58, 123, 34, 116, 111, 107, 101, 110, 34, 58, 34, 52, 56, 98, 120, 75, 118, 115, 106, 86, 73, 78, 110, 101, 83, 50, 110, 101, 48, 111, 75, 80, 90, 34, 125, 125, 125]] } }
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::dealer) No subscriber for msg.uri: social-connect/v2/broadcast_status_update
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::state) reset_playback with active ctx <Default> fill_up ctx <Default>
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) failed filling up next_track during stopping: Invalid state { context is not available. type: Default }
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_playback::player) command=Stop
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) session update: <Ok(NEW_SESSION)> for self, current session_id 860a0f014ea7b57b565dad571767542e, new session_id 73cac0deadf9fc57f159ab4a987b73ca
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:4M7El604yMVdNJQEY6NfyZ
Apr 14 08:04:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) could not parse session_update: Invalid state { Unknown enum variant name: `WIFI_BROADCAST_CHANGED` at 1:11 }
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=3605839043
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:4M7El604yMVdNJQEY6NfyZ
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling next context Some("spotify:playlist:4M7El604yMVdNJQEY6NfyZ")
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) updated context Default to <Some("spotify:playlist:4M7El604yMVdNJQEY6NfyZ")> (153 tracks)
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::context_resolver) last item of type <Default>, finishing state setup
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state::transfer) active track is <spotify:track:4Wglx410HPppBEo3oi79k0> with index Ok(12) in Default context, has 153 tracks
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state::transfer) setting up next and prev: index is at Some(12) while shuffle false
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state) reset_playback with active ctx <Default> fill_up ctx <Default>
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) set track to: spotify:track:4Wglx410HPppBEo3oi79k0 at 12 of 153 tracks
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state) has 10 prev tracks
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) finished filling up next_tracks (80)
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=4064738351
Apr 14 08:04:33 hppd600-g3 snapserver[202970]: (librespot_playback::player) <Made In The Sky - Artena Remix> (224987 ms) loaded
Apr 14 08:06:22 hppd600-g3 snapserver[202970]: (librespot_core::session) Session strong=6 weak=8
Apr 14 08:06:32 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 684310e8b1acf05ac40495c8e1371fdc7d66df06, active device:
Apr 14 08:06:34 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) cluster update: Ok(UNKNOWN_CLUSTER_UPDATE_REASON) from 684310e8b1acf05ac40495c8e1371fdc7d66df06, active device:
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling: 'endpoint: transfer' from 684310e8b1acf05ac40495c8e1371fdc7d66df06
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) found initial track <spotify:track:4Wglx410HPppBEo3oi79k0>
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_playback::player) command=Load(SpotifyId("spotify:track:4Wglx410HPppBEo3oi79k0"), false, 65626)
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=2954037122
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/a24de0c3c03d4d8692e6e2806dad3da4?product=0&country=NZ&salt=622825189
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_playback::player) Loading <Made In The Sky - Artena Remix> with Spotify URI <spotify:track:4Wglx410HPppBEo3oi79k0>
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_audio::fetch) Downloading file d7b4d96d6d6734be3a28b8963797f064375f8a96
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/storage-resolve/files/audio/interactive/d7b4d96d6d6734be3a28b8963797f064375f8a96?product=0&country=NZ&salt=1433694279
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_core::dealer::manager) replying to ws request: Success
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:38 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=1921732423
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:track:4Wglx410HPppBEo3oi79k0
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling next context Some("")
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) updated context Default to <Some("")> (1 tracks)
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::context_resolver) last item of type <Default>, finishing state setup
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state::transfer) active track is <spotify:track:4Wglx410HPppBEo3oi79k0> with index Ok(0) in Default context, has 1 tracks
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state::transfer) setting up next and prev: index is at Some(0) while shuffle false
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state) reset_playback with active ctx <Default> fill_up ctx <Default>
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) set track to: spotify:track:4Wglx410HPppBEo3oi79k0 at 0 of 1 tracks
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) finished filling up next_tracks (0)
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=2357157650
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/autoplay
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_playback::player) <Made In The Sky - Artena Remix> (224987 ms) loaded
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:39 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=4080393658
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/autoplay
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling next context Some("spotify:station:track:4Wglx410HPppBEo3oi79k0")
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) updated context Autoplay to <Some("spotify:station:track:4Wglx410HPppBEo3oi79k0")> (50 tracks)
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_connect::context_resolver) last item of type <Autoplay>, finishing state setup
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) finished filling up next_tracks (51)
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:06:40 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=554273808
Apr 14 08:06:56 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling: 'endpoint: play' from 684310e8b1acf05ac40495c8e1371fdc7d66df06
Apr 14 08:06:56 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 14 08:06:56 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) couldn't load context info because: context is not available. type: Default
Apr 14 08:06:56 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) resolving context for load command
Apr 14 08:06:56 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/context-resolve/v1/spotify:playlist:1KeLRHq4xFEXmUVpn1ylql
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling next context Some("spotify:playlist:1KeLRHq4xFEXmUVpn1ylql")
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::context) updated context Default to <Some("spotify:playlist:1KeLRHq4xFEXmUVpn1ylql")> (31 tracks)
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::context_resolver) last item of type <Default>, finishing state setup
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state) reset_playback with active ctx <Default> fill_up ctx <Default>
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) set track to: spotify:track:5vNRhkKd0yEAg8suGBpjeY at 0 of 31 tracks
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) finished filling up next_tracks (30)
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) play track <None>
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) loading with shuffle: <false>, repeat track: <false> context: <false>
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) set track to: spotify:track:5vNRhkKd0yEAg8suGBpjeY at 0 of 31 tracks
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state) reset_playback with active ctx <Default> fill_up ctx <Default>
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) set track to: spotify:track:5vNRhkKd0yEAg8suGBpjeY at 0 of 31 tracks
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state::tracks) finished filling up next_tracks (30)
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: false, buffering: true
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_core::dealer::manager) replying to ws request: Success
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_playback::player) command=Load(SpotifyId("spotify:track:5vNRhkKd0yEAg8suGBpjeY"), true, 0)
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/metadata/4/track/b5238dca5f7741a7bb019447836fd9b4?product=0&country=NZ&salt=3555836752
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: false, buffering: true
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_connect::state) update position to 0:00 at 20:06:57.357
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=545217998
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_playback::player) Loading <APT.> with Spotify URI <spotify:track:5vNRhkKd0yEAg8suGBpjeY>
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_audio::fetch) Downloading file d5bc117a3840617999f663da236c8f6bffbe9954
Apr 14 08:06:57 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/storage-resolve/files/audio/interactive/d5bc117a3840617999f663da236c8f6bffbe9954?product=0&country=NZ&salt=1355557138
Apr 14 08:06:58 hppd600-g3 snapserver[202970]: (librespot_playback::player) <APT.> (169917 ms) loaded
Apr 14 08:06:58 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: false, buffering: false
Apr 14 08:06:58 hppd600-g3 snapserver[202970]: (librespot_connect::state) update position to 0:00 at 20:06:58.342
Apr 14 08:06:58 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=3351913997
Apr 14 08:06:59 hppd600-g3 snapserver[202970]: (librespot_audio::fetch) Downloading file d5bc117a3840617999f663da236c8f6bffbe9954 complete
Apr 14 08:07:00 hppd600-g3 snapserver[202970]: (librespot_connect::spirc) handling: 'endpoint: pause' from 684310e8b1acf05ac40495c8e1371fdc7d66df06
Apr 14 08:07:00 hppd600-g3 snapserver[202970]: (librespot_core::dealer::manager) replying to ws request: Success
Apr 14 08:07:00 hppd600-g3 snapserver[202970]: (librespot_playback::player) command=Pause
Apr 14 08:07:00 hppd600-g3 snapserver[202970]: (librespot_connect::state) updated connect play status playing: true, paused: true, buffering: true
Apr 14 08:07:00 hppd600-g3 snapserver[202970]: (librespot_core::http_client) Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/41e2e061fdf52171ca7dae566f6868cfb4db1513?product=0&country=NZ&salt=2217980892

[roldengarm]

Quick update, I just tried connecting again, and even after trying 4 times it doesn't work; it disconnects quickly after selecting it in the Android app. Please see the librespot logs here: https://pastebin.com/QHrqtmSB

After switching a song, the same problem exists, but I see other things in the logs, it has some service unavailable logs.
https://pastebin.com/NDt0sAy6

[kingosticks]

Are you able to reproduce this with a non-android Spotify client?

[roldengarm]

Are you able to reproduce this with a non-android Spotify client?

Unfortunately currently only have Android devices in the house with which we do all music. For some reason it has stopped showing up on Spotify Web, but I hardly use that. I could try installing Spotify desktop on a Windows machine if that's important.

[photovoltex]

For some reason it has stopped showing up on Spotify Web

When you play music on librespot and are logged in, with the same account, in the web-player, it should show up as device.

I could try installing Spotify desktop on a Windows machine if that's important.

The mobile and desktop clients have some minor and major behavior differences. I would suspect hasn't anything to do with that, but it would be worth a try I would say.

[roldengarm]

@photovoltex @kingosticks interesting. When I connect from Spotify on Windows, it works fine, ie it does not disconnect. When I open the Android app, it then also shows as connected.
However, when I disconnect, I can't connect again from the Android app.

Hope this helps with your investigation.

[roldengarm]

@photovoltex @kingosticks As a trial I've deployed Snapserver + Librespot in a docker container and then it seems to work fine.
Unsure why it doesn't work well when directly running from the host.

[photovoltex]

Interesting, thanks for letting us know. So the whole issue might be platform/environment dependent then?

[roldengarm]

Yeah perhaps @photovoltex but this way I have less control over the software installed.
Any idea why it doesn't work well directly on the host? Did you have a chance to check the logs I uploaded?

[ReasonableHippo]

I have the same issue. Can't connect from android client with the
[2025-04-20T09:14:08Z ERROR librespot_connect::spirc] could not parse session_update: Invalid state { Unknown enum variant name: WIFI_BROADCAST_CHANGED at 1:11 }
messages, but it works from the web interface. If the web-player is open, i can also control from android.

Its version 0.6.0 running in a docker container on armv7l

[497e0bdf29873]

I have the same issue, running librespot standalone on Armbian on an Orange Pi 5b. It just disappears and has to be restarted. Here are the relevant logs. In particular, 15:00:09 seems relevant. 19:24:19 is already a restart after it had disappeared.

May 06 08:55:38 xxxx run-librespot[286319]: [2025-05-06T13:55:38Z INFO  librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
May 06 08:55:38 xxxx run-librespot[286319]: [2025-05-06T13:55:38Z INFO  librespot_connect::spirc] active device is <> with session <65ae3c928ed9c0bd88c001e0d6e05151>
May 06 09:06:38 xxxx run-librespot[286319]: [2025-05-06T14:06:38Z ERROR librespot_core::session] Connection to server closed.
May 06 09:41:34 xxxx run-librespot[286319]: [2025-05-06T14:41:34Z WARN  librespot_core::dealer] Websocket connection failed: IO error: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
May 06 09:41:34 xxxx run-librespot[286319]: [2025-05-06T14:41:34Z WARN  librespot] Spirc shut down unexpectedly
May 06 09:41:34 xxxx run-librespot[286319]: [2025-05-06T14:41:34Z ERROR librespot_core::session] Transport endpoint is not connected (os error 107)
May 06 09:41:35 xxxx run-librespot[286319]: [2025-05-06T14:41:35Z INFO  librespot_core::session] Connecting to AP "ap-guc3.spotify.com:4070"
May 06 09:41:36 xxxx run-librespot[286319]: [2025-05-06T14:41:36Z INFO  librespot_core::session] Authenticated as 'xxxxxx' !
May 06 09:41:36 xxxx run-librespot[286319]: [2025-05-06T14:41:36Z INFO  librespot_core::session] Country: "XX"
May 06 09:41:36 xxxx run-librespot[286319]: [2025-05-06T14:41:36Z INFO  librespot_core::spclient] Resolved "guc3-spclient.spotify.com:443" as spclient access point
May 06 09:41:37 xxxx run-librespot[286319]: [2025-05-06T14:41:37Z INFO  librespot_connect::spirc] active device is <> with session <65ae3c928ed9c0bd88c001e0d6e05151>
May 06 11:05:33 xxxx run-librespot[286319]: [2025-05-06T16:05:33Z WARN  librespot_core::dealer] No subscriber for msg.uri: social-connect/v2/broadcast_status_update
May 06 15:00:09 xxxx run-librespot[286319]: [2025-05-06T20:00:09Z WARN  librespot_core::dealer] Websocket peer does not respond.
May 06 19:24:19 xxxx run-librespot[291821]: [2025-05-07T00:24:19Z INFO  librespot] librespot 0.6.0-dev 59381cc (Built on 2025-04-28, Build ID: aUgHcXaK, Profile: release)