[GH-ISSUE #238] Failed handling dealer request: failed seeking stream: failed reading page: EOF #149

Closed
opened 2026-02-28 14:25:47 +03:00 by kerem · 10 comments
Owner

Originally created by @2opremio on GitHub (Oct 27, 2025).
Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/238

Oct 21 23:24:27 duchamp go-librespot[18070]: time="2025-10-21T23:24:27Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:3SFXsFpeGmBTtQvKiwYMDA: failed seeking stream: failed reading page: EOF"

This all happens through playback transfer requests using github.com/zmb3/spotify, which used to work just fine (in case it helps). Now it tends to fail with golibrespot has been inactive for a while.

Originally created by @2opremio on GitHub (Oct 27, 2025). Original GitHub issue: https://github.com/devgianlu/go-librespot/issues/238 ``` Oct 21 23:24:27 duchamp go-librespot[18070]: time="2025-10-21T23:24:27Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:3SFXsFpeGmBTtQvKiwYMDA: failed seeking stream: failed reading page: EOF" ``` This all happens through playback transfer requests using github.com/zmb3/spotify, which used to work just fine (in case it helps). Now it tends to fail with golibrespot has been inactive for a while.
kerem 2026-02-28 14:25:47 +03:00
  • closed this issue
  • added the
    bug
    label
Author
Owner

@2opremio commented on GitHub (Nov 4, 2025):

Happened today again.

Nov 04 00:58:02 duchamp go-librespot[23113]: time="2025-11-04T00:58:02Z" level=info msg="authenticated AP" username="aa***ta"
Nov 04 10:07:57 duchamp go-librespot[23113]: time="2025-11-04T10:07:57Z" level=info msg="authenticated Login5" username="aa***ta"
Nov 04 10:07:57 duchamp go-librespot[23113]: time="2025-11-04T10:07:57Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:6YX1xvYEee7Jva9VOGpoFO: failed seeking stream: failed reading page: EOF"

This always happens when transfering sessions BTW. There may be a problem when setting up the context of a song when it's playback comes from a session transfer.

<!-- gh-comment-id:3485089600 --> @2opremio commented on GitHub (Nov 4, 2025): Happened today again. ``` Nov 04 00:58:02 duchamp go-librespot[23113]: time="2025-11-04T00:58:02Z" level=info msg="authenticated AP" username="aa***ta" Nov 04 10:07:57 duchamp go-librespot[23113]: time="2025-11-04T10:07:57Z" level=info msg="authenticated Login5" username="aa***ta" Nov 04 10:07:57 duchamp go-librespot[23113]: time="2025-11-04T10:07:57Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:6YX1xvYEee7Jva9VOGpoFO: failed seeking stream: failed reading page: EOF" ``` This always happens when transfering sessions BTW. There may be a problem when setting up the context of a song when it's playback comes from a session transfer.
Author
Owner

@devgianlu commented on GitHub (Nov 4, 2025):

The failed reading page: EOF error comes from the Vorbis decoder. It seems that a seek is being made to the very end of the track.

There should be a log saying loading ... (paused: ..., position: ...ms) if you increase log level to debug, can you try that and share a log?

<!-- gh-comment-id:3487087567 --> @devgianlu commented on GitHub (Nov 4, 2025): The `failed reading page: EOF` error comes from the Vorbis decoder. It seems that a seek is being made to the very end of the track. There should be a log saying `loading ... (paused: ..., position: ...ms)` if you increase log level to `debug`, can you try that and share a log?
Author
Owner

@2opremio commented on GitHub (Nov 4, 2025):

At trace level:

Nov 04 17:19:10 duchamp go-librespot[25401]: time="2025-11-04T17:19:10Z" level=trace msg="sent dealer ping"
Nov 04 17:19:10 duchamp go-librespot[25401]: time="2025-11-04T17:19:10Z" level=trace msg="received dealer pong"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="handling transfer player command from webapi-2d290401879840a892429081c626417f"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="resolved context of track" uri="spotify:artist:4YcQuAswXPWdO2WAxTRXse"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:artist:4YcQuAswXPWdO2WAxTRXse"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="loading track (paused: false, position: 34205868ms)" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="emitting websocket event: will_play"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="selected format OGG_VORBIS_320 (af387390a7f85254ea94d2f4f92ea4579f1cbfc8)" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="requested aes key for file af387390a7f85254ea94d2f4f92ea4579f1cbfc8, gid: 6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="found 2 cdn urls" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched first chunk of 14, total size is 7294747 bytes" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 13/13, size: 479003" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:6YX1xvYEee7Jva9VOGpoFO: failed seeking stream: failed reading page: EOF"
Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO"
Nov 04 17:19:40 duchamp go-librespot[25401]: time="2025-11-04T17:19:40Z" level=trace msg="sent dealer ping"
Nov 04 17:19:40 duchamp go-librespot[25401]: time="2025-11-04T17:19:40Z" level=trace msg="received dealer pong"
Nov 04 17:20:10 duchamp go-librespot[25401]: time="2025-11-04T17:20:10Z" level=trace msg="sent dealer ping"
Nov 04 17:20:10 duchamp go-librespot[25401]: time="2025-11-04T17:20:10Z" level=trace msg="received dealer pong"
<!-- gh-comment-id:3487184260 --> @2opremio commented on GitHub (Nov 4, 2025): At trace level: ``` Nov 04 17:19:10 duchamp go-librespot[25401]: time="2025-11-04T17:19:10Z" level=trace msg="sent dealer ping" Nov 04 17:19:10 duchamp go-librespot[25401]: time="2025-11-04T17:19:10Z" level=trace msg="received dealer pong" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="handling transfer player command from webapi-2d290401879840a892429081c626417f" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="resolved context of track" uri="spotify:artist:4YcQuAswXPWdO2WAxTRXse" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:artist:4YcQuAswXPWdO2WAxTRXse" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="loading track (paused: false, position: 34205868ms)" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="emitting websocket event: will_play" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="selected format OGG_VORBIS_320 (af387390a7f85254ea94d2f4f92ea4579f1cbfc8)" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="requested aes key for file af387390a7f85254ea94d2f4f92ea4579f1cbfc8, gid: 6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=trace msg="found 2 cdn urls" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched first chunk of 14, total size is 7294747 bytes" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 13/13, size: 479003" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:6YX1xvYEee7Jva9VOGpoFO: failed seeking stream: failed reading page: EOF" Nov 04 17:19:22 duchamp go-librespot[25401]: time="2025-11-04T17:19:22Z" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:6YX1xvYEee7Jva9VOGpoFO" Nov 04 17:19:40 duchamp go-librespot[25401]: time="2025-11-04T17:19:40Z" level=trace msg="sent dealer ping" Nov 04 17:19:40 duchamp go-librespot[25401]: time="2025-11-04T17:19:40Z" level=trace msg="received dealer pong" Nov 04 17:20:10 duchamp go-librespot[25401]: time="2025-11-04T17:20:10Z" level=trace msg="sent dealer ping" Nov 04 17:20:10 duchamp go-librespot[25401]: time="2025-11-04T17:20:10Z" level=trace msg="received dealer pong" ```
Author
Owner

@2opremio commented on GitHub (Nov 4, 2025):

The late chunk 3/13 printout (and lack of the remaining chunk printous), makes it seems like the piece to seek to may be in chunk yet to be downloaded?

Maybe there is a synchronization problem with the downloading goroutines? (I am assuming, since I haven't checked the code)

<!-- gh-comment-id:3487194228 --> @2opremio commented on GitHub (Nov 4, 2025): The late `chunk 3/13` printout (and lack of the remaining chunk printous), makes it seems like the piece to seek to may be in chunk yet to be downloaded? Maybe there is a synchronization problem with the downloading goroutines? (I am assuming, since I haven't checked the code)
Author
Owner

@devgianlu commented on GitHub (Nov 4, 2025):

The track is ~120 seconds, but the seek is requested at ~34205 seconds (~9.5 hours). go-librespot will cap this at the track duration, causing the seek to EOF because it's technically past the end of track.

The problem seems that the timestamps coming in are messed up. Since the player is not paused the track position is calculated as

now_unix - spotify_update_time + spotify_position_as_of_update

These values are not present in the log, but I assume spotify_update_time is the one messed up. I have no idea why that would be since it's all coming from Spotify directly. Is this a Spotify bug?


Regarding the fetching of the chunks, it's all fine. The first chunk is loaded to read the Ogg metadata causing the prefetching of the next couple of chunks. In the meantime the seek requests the last chunks and that is fetched too.

<!-- gh-comment-id:3487288089 --> @devgianlu commented on GitHub (Nov 4, 2025): The track is ~120 seconds, but the seek is requested at ~34205 seconds (~9.5 hours). `go-librespot` will cap this at the track duration, causing the seek to EOF because it's technically past the end of track. The problem seems that the timestamps coming in are messed up. Since the player is not paused the track position is calculated as ``` now_unix - spotify_update_time + spotify_position_as_of_update ``` These values are not present in the log, but I assume `spotify_update_time` is the one messed up. I have no idea why that would be since it's all coming from Spotify directly. Is this a Spotify bug? ---- Regarding the fetching of the chunks, it's all fine. The first chunk is loaded to read the Ogg metadata causing the prefetching of the next couple of chunks. In the meantime the seek requests the last chunks and that is fetched too.
Author
Owner

@2opremio commented on GitHub (Nov 4, 2025):

Is this a Spotify bug?

Maybe! I am just using github.com/zmb3/spotify for the transfers, and AFAIU I am not sending any explicit seek times.

<!-- gh-comment-id:3487503271 --> @2opremio commented on GitHub (Nov 4, 2025): > Is this a Spotify bug? Maybe! I am just using github.com/zmb3/spotify for the transfers, and AFAIU I am not sending any explicit seek times.
Author
Owner

@2opremio commented on GitHub (Nov 5, 2025):

Also, the player is definitely and 100% not playing at the time I am transferring the context (neither the local one nor golibrespot). Maybe the code is making a wrong assumption there?

Either way, can we at least start the track from the beginning of the week time doesn’t make sense?

<!-- gh-comment-id:3488704894 --> @2opremio commented on GitHub (Nov 5, 2025): Also, the player is definitely and 100% not playing at the time I am transferring the context (neither the local one nor golibrespot). Maybe the code is making a wrong assumption there? Either way, can we at least start the track from the beginning of the week time doesn’t make sense?
Author
Owner

@2opremio commented on GitHub (Nov 5, 2025):

I think paused=false only means continue playing not the fact that the player is active or not …

<!-- gh-comment-id:3488710090 --> @2opremio commented on GitHub (Nov 5, 2025): I think paused=false only means continue playing not the fact that the player is active or not …
Author
Owner

@2opremio commented on GitHub (Nov 6, 2025):

I think I found the root cause. When paused=false, the code assumes that playback is active and calculates position dynamically, but paused=false only means "continue playing" (intent), not that playback is actually active.

During transfers, neither player is actively playing, so the timestamp can be stale (from a previous session). Calculating now - old_timestamp gives a huge elapsed time that pushes position way beyond track duration.

Looking at cmd/daemon/state.go, trackPosition() only checks IsPaused and doesn't check IsPlaying. The proto/spotify/connectstate/player.proto has both is_paused and is_playing fields.

The original librespot (Rust) handles this in connect/src/state.rs:

  • They check is_playing() which requires player.is_playing && !player.is_paused before calculating dynamic position
  • They validate timestamps and use raw position when stale - see update_position_in_relation()
  • They always cap position to [0, track_duration] in spirc.rs

The fix should check IsPlaying (not just IsPaused) before calculating dynamic position, validate timestamp freshness, and fall back to raw position when timestamp is stale or playback isn't active.

I have created a PR doing this at #247. I tested it on my system and seems to fix the problem.

<!-- gh-comment-id:3494380530 --> @2opremio commented on GitHub (Nov 6, 2025): I think I found the root cause. When `paused=false`, the code assumes that playback is active and calculates position dynamically, but `paused=false` only means "continue playing" (intent), not that playback is actually active. During transfers, neither player is actively playing, so the `timestamp` can be stale (from a previous session). Calculating `now - old_timestamp` gives a huge elapsed time that pushes position way beyond track duration. Looking at [`cmd/daemon/state.go`](https://github.com/devgianlu/go-librespot/blob/8ca49aa88886600b6bf8b8175f36b4cdbed5b068/cmd/daemon/state.go#L66-L71), `trackPosition()` only checks `IsPaused` and doesn't check `IsPlaying`. The [`proto/spotify/connectstate/player.proto`](https://github.com/devgianlu/go-librespot/blob/8ca49aa88886600b6bf8b8175f36b4cdbed5b068/proto/spotify/connectstate/player.proto#L5-L18) has both `is_paused` and `is_playing` fields. The original librespot (Rust) handles this in [`connect/src/state.rs`](https://github.com/librespot-org/librespot/blob/master/connect/src/state.rs#L370-L375): - They check [`is_playing()`](https://github.com/librespot-org/librespot/blob/master/connect/src/state.rs#L258-L263) which requires `player.is_playing && !player.is_paused` before calculating dynamic position - They validate timestamps and use raw position when stale - see [`update_position_in_relation()`](https://github.com/librespot-org/librespot/blob/master/connect/src/state.rs#L435-L450) - They always cap position to `[0, track_duration]` in [`spirc.rs`](https://github.com/librespot-org/librespot/blob/master/connect/src/spirc.rs#L374-L375) The fix should check `IsPlaying` (not just `IsPaused`) before calculating dynamic position, validate timestamp freshness, and fall back to raw position when timestamp is stale or playback isn't active. I have created a PR doing this at [#247](https://github.com/devgianlu/go-librespot/pull/247). I tested it on my system and seems to fix the problem.
Author
Owner

@devgianlu commented on GitHub (Nov 6, 2025):

Thanks!

<!-- gh-comment-id:3495870793 --> @devgianlu commented on GitHub (Nov 6, 2025): Thanks!
Sign in to join this conversation.
No milestone
No project
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/go-librespot#149
No description provided.