starred/librespot
1
0
Fork 0
mirror of https://github.com/librespot-org/librespot.git synced 2026-04-27 08:15:50 +03:00
Code Issues 95 Projects Releases 10 Packages Wiki Activity

[GH-ISSUE #1472] Unexpected exit due to "seek timestamp is out-of-range" #661

New issue
Open
opened 2026-02-27 19:31:49 +03:00 by kerem · 7 comments
kerem commented 2026-02-27 19:31:49 +03:00
Owner
Copy link

Originally created by @Malvineous on GitHub (Feb 27, 2025).
Original GitHub issue: https://github.com/librespot-org/librespot/issues/1472

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.

Originally created by @Malvineous on GitHub (Feb 27, 2025). Original GitHub issue: https://github.com/librespot-org/librespot/issues/1472 ### 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.
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@Malvineous commented on GitHub (Mar 3, 2025):

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)
<!-- gh-comment-id:2693775120 --> @Malvineous commented on GitHub (Mar 3, 2025): 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) ```
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@photovoltex commented on GitHub (Mar 3, 2025):

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.

<!-- gh-comment-id:2694514997 --> @photovoltex commented on GitHub (Mar 3, 2025): 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.
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@Malvineous commented on GitHub (Mar 3, 2025):

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?

<!-- gh-comment-id:2694585747 --> @Malvineous commented on GitHub (Mar 3, 2025): 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?
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@roldengarm commented on GitHub (Apr 2, 2025):

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.

<!-- gh-comment-id:2773791688 --> @roldengarm commented on GitHub (Apr 2, 2025): I'm trying to integrate Home Assistant with Spotify Plus, using the [SpotifyPlus integration](https://github.com/thlucas1/homeassistantcomponent_spotifyplus/), 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.
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@roderickvd commented on GitHub (Apr 3, 2025):

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.

<!-- gh-comment-id:2776526379 --> @roderickvd commented on GitHub (Apr 3, 2025): 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](https://github.com/roderickvd/pleezer/blob/33dc67217258fb219900a8efd8d36e2cd0294264/src/decoder.rs#L587). I'll see if I can propose a small PR for it.
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@roderickvd commented on GitHub (Apr 4, 2025):

Please give #1483 a spin.

<!-- gh-comment-id:2779622451 --> @roderickvd commented on GitHub (Apr 4, 2025): Please give #1483 a spin.
kerem commented 2026-02-27 19:31:50 +03:00
Author
Owner
Copy link

@roderickvd commented on GitHub (Apr 6, 2025):

Re-opening as the real fix should be in the websocket handler.

<!-- gh-comment-id:2781553005 --> @roderickvd commented on GitHub (Apr 6, 2025): Re-opening as the real fix should be in the websocket handler.
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
dev
v0.8.0
v0.7.1
v0.7.0
v0.6.0
v0.5.0
v0.4.2
v0.4.1
v0.4.0
v0.3.1
v0.3.0
v0.2.0
v0.1.6
v0.1.5
v0.1.3
v0.1.2
v0.1.1
v0.1.0
Labels
Clear labels   
A-Alsa

   
SpotifyAPI

   
Tokio 1.0

   
audio

   
bug

   
can't reproduce

   
compilation

   
dependencies

   
duplicate

   
enhancement

   
good first issue

   
help wanted

   
high priority

   
imported

   
imported

   
invalid

   
new api

   
pull-request

Mirrored from GitHub Pull Request

  
question

   
reverse engineering

   
wiki

   
wontfix
No labels
A-Alsa
SpotifyAPI
Tokio 1.0
audio
bug
can't reproduce
compilation
dependencies
duplicate
enhancement
good first issue
help wanted
high priority
imported
imported
invalid
new api
pull-request
question
reverse engineering
wiki
wontfix
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/librespot#661
No description provided.