spirc shuts down and can't re-connect in client

[tonabnehmer]

Description

When running librespot for > 20hours, connection gets dropped and I can't seem to re-connect without restarting the service.

Version

librespot 0.6.0-dev 82076e8 (Built on 2024-11-12, Build ID: lBmK6OcA, Profile: release
Built for raspberry 2

How to reproduce

Steps to reproduce the behavior in librespot e.g.

1. Launch librespot with -b 320 -c /tmp/spotcache
2. Connect with auth in credentials.json
3. In the client click on connect to device
4. See some error/problem after some time 'spirc' shuts down and I can't reconnect

Log

Bigger log: https://pastebin.com/kpLGe8rr
Smaller log:

Nov 29 06:58:02 raspberrypi librespot[30323]: [2024-11-29T05:58:02Z DEBUG librespot_connect::spirc] successfully pre-acquire access_token and client_token
Nov 29 06:59:01 raspberrypi librespot[30323]: [2024-11-29T05:59:01Z TRACE librespot_core::session] Sending Pong
Nov 29 06:59:01 raspberrypi librespot[30323]: [2024-11-29T05:59:01Z TRACE librespot_core::session] keep-alive state: ExpectingPongAck, timeout in 20.0
Nov 29 06:59:02 raspberrypi librespot[30323]: [2024-11-29T05:59:02Z TRACE librespot_core::session] Received PongAck
Nov 29 06:59:02 raspberrypi librespot[30323]: [2024-11-29T05:59:02Z TRACE librespot_core::session] keep-alive state: ExpectingPing, timeout in 80.0
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::session] Shutdown: Invalidating session
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] new ChannelManager
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::session] drop Dispatch
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z ERROR librespot_connect::spirc] remote update selected, but none received
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_connect::spirc] drop Spirc[511]
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z WARN  librespot] Spirc shut down unexpectedly
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::session] new Session
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_connect::spirc] new Spirc[512]
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] new MercuryManager
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_playback::player] command=SetSession
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::session] drop Session
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] new SpClient
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] drop ApResolver
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] drop ChannelManager
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] drop MercuryManager
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] drop SpClient
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot::component] drop Login5Manager
Nov 29 07:00:22 raspberrypi librespot[30323]: [2024-11-29T06:00:22Z DEBUG librespot_core::spclient] Received a granted token

Host (what you are running librespot on):

• OS: raspian 12, kernel /etc/*-release
• Platform: RPi 2

Additional context

If needed can post the bigger log file as well. Seemed to work pre 0.5.0-dev

[kingosticks]

The session ends because you didn't receive a keep-alive ping from Spotify. That's likely a problem on their end, or perhaps even a network issue (but that would be more random). Either way, closing the session is correct behaviour.

Full log would be good, it's not clear from this snippet where the failure to reconnect afterwards is, or why it might happen.

[tonabnehmer]

Very odd, but after closing the session shouldn't there be a re-connect? Added the pastebin log to the ticket, https://pastebin.com/kpLGe8rr

[kingosticks]

Yes, it should reconnect, I was alluding to that in my second paragraph. Thanks for log, will take a look later.