librespot-org
Unexpected exit due to "seek timestamp is out-of-range"
Description
librespot exits due to a decoder error, when it should just continue with the next song.
librespot_playback::player] Error handling command: Operation aborted {
Symphonia Decoder Error: seek error: requested seek timestamp is out-of-range for stream }
librespot_playback::player] PlayerState::is_playing in invalid state
(process terminated)
Version
git from 2024-12-30
How to reproduce
Hard to reproduce, intermittent. Seems to happen when the connection drops out briefly.
Log
All the log output was normal except for this at the end:
[2025-02-27T01:10:22Z DEBUG librespot_connect::spirc] handling: 'endpoint: transfer' from 966faa16860f7e3e9cc0f1cea01ae5ed18948460
[2025-02-27T01:10:22Z DEBUG librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-02-27T01:10:22Z DEBUG librespot_connect::spirc] found initial track <spotify:track:xxx>
[2025-02-27T01:10:22Z DEBUG librespot_connect::spirc] add resolve request: resolve_uri: <Some("spotify:playlist:xxx")>, context_uri: <Some("spotify:playlist:xxx")>, autoplay: <false>, update: <true>
[2025-02-27T01:10:22Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-02-27T01:10:22Z DEBUG librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[2025-02-27T01:10:22Z ERROR librespot_playback::player] Error handling command: Operation aborted { Symphonia Decoder Error: seek error: requested seek timestamp is out-of-range for stream }
[2025-02-27T01:10:22Z ERROR librespot_playback::player] PlayerState::is_playing in invalid state
It happened overnight and when I woke up, the Spotify UI was saying it was 8 hours into a three minute song, paused, but librespot had disconnected so it was no longer selected as the playback device.
Restarting librespot and playing the same song again worked fine, so the song itself was not the problem, it seems like the communication interruption was more likely the cause.
Host (what you are running librespot on):
Linux, PC
Additional context
I'm just reporting this as I think that "timestamp out of range" Symphonia error should really be treated as a minor error (or just 'end of current song'), it shouldn't cause the whole application to terminate because of it.
Weirdly I seem to be getting this issue daily now, sometimes multiple times a day.
[2025-03-03T09:11:35Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx?product=0&country=AU&salt=xxx
[2025-03-03T09:11:36Z WARN librespot_connect::spirc] unexpected shutdown
[2025-03-03T09:11:36Z DEBUG librespot_connect::state] update position to 0:00 at 9:11:36.403
[2025-03-03T09:11:36Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: false, buffering: true
[2025-03-03T09:11:36Z DEBUG librespot_connect::state] update position to 0:00 at 9:11:36.403
[2025-03-03T09:11:36Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx?product=0&country=AU&salt=xxx
[2025-03-03T09:11:36Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx/inactive?notify=false&product=0&country=AU&salt=xxx
[2025-03-03T09:11:36Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx?product=0&country=AU&salt=xxx
[2025-03-03T09:11:37Z DEBUG librespot_core::dealer] closing dealer
[2025-03-03T09:11:37Z DEBUG librespot_core::dealer] Dropping send task
[2025-03-03T09:11:37Z DEBUG librespot_playback::player] command=EmitSessionDisconnectedEvent("xxx", "xxx")
[2025-03-03T09:11:37Z 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
[2025-03-03T09:11:37Z DEBUG librespot_core::dealer] Dropping receive task
[2025-03-03T09:11:37Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2025-03-03T09:11:37Z WARN librespot] Spirc shut down unexpectedly
[2025-03-03T09:11:37Z DEBUG librespot_core::session] new Session
[2025-03-03T09:11:37Z DEBUG librespot_connect::spirc] new Spirc[1]
[2025-03-03T09:11:37Z DEBUG librespot::component] new DealerManager
[2025-03-03T09:11:37Z DEBUG librespot::component] new SpClient
[2025-03-03T09:11:37Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2025-03-03T09:11:37Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2025-03-03T09:11:37Z DEBUG librespot_playback::player] command=SetSession
[2025-03-03T09:11:37Z DEBUG librespot_core::session] drop Session
[2025-03-03T09:11:37Z DEBUG librespot::component] drop ApResolver
[2025-03-03T09:11:37Z DEBUG librespot::component] drop AudioKeyManager
[2025-03-03T09:11:37Z DEBUG librespot::component] drop ChannelManager
[2025-03-03T09:11:37Z DEBUG librespot::component] drop MercuryManager
[2025-03-03T09:11:37Z DEBUG librespot::component] drop DealerManager
[2025-03-03T09:11:37Z DEBUG librespot::component] drop SpClient
[2025-03-03T09:11:37Z DEBUG librespot::component] drop Login5Manager
[2025-03-03T09:11:37Z DEBUG librespot_core::spclient] Received a granted token
[2025-03-03T09:11:37Z TRACE librespot_core::spclient] Got client token: GrantedTokenResponse { token: "xxx", expires_after_seconds: 1216800, refresh_after_seconds: 1209600, domains: [TokenDomain { domain: "spotify.com", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }, TokenDomain { domain: "spotify.net", special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }], special_fields: SpecialFields { unknown_fields: UnknownFields { fields: None }, cached_size: CachedSize { size: 0 } } }
[2025-03-03T09:11:37Z DEBUG librespot::component] new ApResolver
[2025-03-03T09:11:37Z DEBUG librespot_core::http_client] Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
[2025-03-03T09:11:37Z INFO librespot_core::session] Connecting to AP "ap-gae2.spotify.com:4070"
[2025-03-03T09:11:38Z DEBUG librespot_core::connection] Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
[2025-03-03T09:11:38Z INFO librespot_core::session] Authenticated as 'xxx' !
[2025-03-03T09:11:38Z DEBUG librespot::component] new Login5Manager
[2025-03-03T09:11:38Z DEBUG librespot_core::http_client] Requesting https://login5.spotify.com/v3/login
[2025-03-03T09:11:38Z TRACE librespot_core::session] Received Ping
[2025-03-03T09:11:38Z TRACE librespot_core::session] keep-alive state: PendingPong, timeout in 60.0
[2025-03-03T09:11:38Z DEBUG librespot_core::session] Session strong=5 weak=6
[2025-03-03T09:11:38Z INFO librespot_core::session] Country: "AU"
[2025-03-03T09:11:38Z TRACE librespot_core::session] Received product info: {...
[2025-03-03T09:27:36Z DEBUG librespot::component] new MercuryManager
[2025-03-03T09:27:36Z TRACE librespot_core::mercury] mercury response <hm://pusher/v1/connections/xxx> is handled by dealer
[2025-03-03T09:27:36Z TRACE librespot_core::login5] Got auth token: Token { access_token: "xxx", expires_in: 3600s, token_type: "Bearer", scopes: [], timestamp: Instant { tv_sec: 6715954, tv_nsec: 605774998 } }
[2025-03-03T09:27:36Z DEBUG librespot_playback::player] command=AddEventSender
[2025-03-03T09:27:36Z DEBUG librespot_core::dealer::manager] Launching dealer
[2025-03-03T09:27:36Z TRACE librespot_core::dealer] Sent ping
[2025-03-03T09:27:36Z TRACE librespot_connect::spirc] Received connection ID update: "xxx"
[2025-03-03T09:27:36Z INFO librespot_core::spclient] Resolved "gae2-spclient.spotify.com:443" as spclient access point
[2025-03-03T09:27:36Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx?product=0&country=AU&salt=xxx
[2025-03-03T09:27:36Z TRACE librespot_core::dealer] Received pong
[2025-03-03T09:27:37Z DEBUG librespot_connect::spirc] successfully put connect state for 4cac88a0b6d837ba26b5c2f809827e29f94af828 with connection-id xxx
[2025-03-03T09:27:37Z INFO librespot_connect::spirc] active device is <> with session <xxx>
It just sits there pinging and ponging after this point, but the playback device has changed. When I change the playback device back to librespot, that's when it crashes:
[2025-03-03T09:26:09Z TRACE librespot_core::dealer] Sent ping
[2025-03-03T09:26:09Z TRACE librespot_core::dealer] Received pong
[2025-03-03T09:26:30Z TRACE librespot_core::dealer] dealer request hm://connect-state/v1/player/command
[2025-03-03T09:26:30Z TRACE librespot_core::dealer::protocol] message was send with gzip encoding
[2025-03-03T09:26:30Z TRACE librespot_core::dealer::protocol] websocket request: Object {
"command": Object {
"data": String("CgsIABAAGAAlAAAAA...
"endpoint": String("transfer"),
"from_device_identifier": String("xxx"),
"logging_params": Object {
"command_id": String("97eaa4aaab87750a54801e39cf275ba9"),
"interaction_ids": Array [
String("33b75edb-87d4-4041-b59e-cfdcf6356af6"),
],
},
"options": Object {
"restore_paused": String("restore"),
"restore_position": String("last_known"),
"restore_track": String("always_play_something"),
"retain_session": String("do_not_retain"),
},
},
"message_id": Number(1532235937),
"play_on_secondary_stream": Null,
"sent_by_device_id": String("xxx"),
"target_alias_id": Null,
}
[2025-03-03T09:26:30Z DEBUG librespot_connect::spirc] handling: 'endpoint: transfer' from ee27b00552fa8e89479657ba369fe7a131222def
[2025-03-03T09:26:30Z DEBUG librespot_connect::state::context] couldn't load context info because: context is not available. type: Default
[2025-03-03T09:26:30Z DEBUG librespot_connect::spirc] found initial track <spotify:track:xxx>
[2025-03-03T09:26:30Z DEBUG librespot_connect::spirc] add resolve request: resolve_uri: <Some("spotify:playlist:6n43nxnVFcU3lXlXtieqbe")>, context_uri: <Some("spotify:playlist:xxx")>, autoplay: <false>, update: <true>
[2025-03-03T09:26:30Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-03-03T09:26:30Z DEBUG librespot_connect::state] updated connect play status playing: true, paused: true, buffering: true
[2025-03-03T09:26:30Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:xxx"), false, 894203)
[2025-03-03T09:26:30Z DEBUG librespot_core::http_client] Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/xxx?product=0&country=AU&salt=xxx
[2025-03-03T09:26:30Z ERROR librespot_playback::player] Error handling command: Operation aborted { Symphonia Decoder Error: seek error: requested seek timestamp is out-of-range for stream }
[2025-03-03T09:26:30Z ERROR librespot_playback::player] PlayerState::is_playing in invalid state
(process terminates)
Thanks for the detailed report^^
Seems like the seeking evaluates a incorrect position where to resume. Probably because we dropped the state in a running position probably because we wan't to restart the dealer and pickup the playing state, but don't do so automatically :/. Might have to adjust the behavior again so that it handles this kinda of dropout correclty.
It seems to try to seek to 894203 milliseconds which would be around ~14 minutes. If I remember correct I had a similar behavior at some point where I would seek out of bounds, but I remember that the player handled that correct and did resume at the begining as fallback. Might have to check that behavior later.
It is a bit odd because it has been happening on short songs too, but the web player also displays strange timestamps, like 9 hours into a three minute song, so not really sure what's going on there.
I don't think I've changed anything though (not even a reboot) since it started happening, so maybe a change on Spotify's end triggered it?
I'm trying to integrate Home Assistant with Spotify Plus, using the SpotifyPlus integration, and I'm seeing the same behaviour here. It tries to start at 494128 but that's out of bounds, it's a much shorter son. Logs:
Apr 03 10:30:32 snapserver[1576666]: Resolved "gae2-spclient.spotify.com:443" as spclient access point
Apr 03 10:30:32 snapserver[1576666]: Requesting https://gae2-spclient.spotify.com:443/connect-state/v1/devices/68...?product=0&country=..&salt=..
Apr 03 10:30:32 snapserver[1576666]: getNextMessage: Time, size: 8, id: 7316, refers: 0
Apr 03 10:30:32 snapserver[1576666]: onMessageReceived: Time, size: 8, id: 7316, refers: 0, sent: 438558,673558, recv: 1377346,982922
Apr 03 10:30:32 snapserver[1576666]: getNextMessage: Time, size: 8, id: 4880, refers: 0
Apr 03 10:30:32 snapserver[1576666]: onMessageReceived: Time, size: 8, id: 4880, refers: 0, sent: 1780960,495614, recv: 1377347,879
Apr 03 10:30:33 snapserver[1576666]: on_read_ws, ec: system:0, bytes_transferred: 34
Apr 03 10:30:33 snapserver[1576666]: getNextMessage: Time, size: 34, id: 699, refers: 0
Apr 03 10:30:33 snapserver[1576666]: onMessageReceived: Time, size: 34, id: 699, refers: 0, sent: 702,151111, recv: 1377347,275656
Apr 03 10:30:33 snapserver[1576666]: successfully put connect state for 68.... with connection-id ZWR....=
Apr 03 10:30:33 snapserver[1576666]: trying to take over control automatically, session_id:
Apr 03 10:30:33 snapserver[1576666]: couldn't load context info because: context is not available. type: Default
Apr 03 10:30:33 snapserver[1576666]: found initial track <spotify:track:5iP6VWh8goBkJcXBMQSejA>
Apr 03 10:30:33 snapserver[1576666]: command=Load(SpotifyId("spotify:track:5iP6VWh8goBkJcXBMQSejA"), false, 494128)
Apr 03 10:30:33 snapserver[1576666]: Error handling command: Operation aborted { Symphonia Decoder Error: seek error: requested seek timestamp is out-of-range for stream }
From the Spotify mobile app and Spotify Web it all works fine, so not sure why it doesn't work from the HA integration.
At least librespot could be made more robust by "saturating" the seek, meaning: clamping a seek target position to the duration of the song like here. I'll see if I can propose a small PR for it.
