[Bug] "spclient request returned bad gateway" and "context deadline exceeded" when trying connect from desktop/mobile app

[szygmunt]

Hi, I’m having an issue with go-librespot.

After starting the service on my Raspberry Pi, it connects and authenticates fine, but when I try to connect from my android phone it can't pair with go-librespot running on Rpi. The log keeps showing “spclient request returned bad gateway” and finally “context deadline exceeded”.

Here’s the full log from systemd:

paź 25 19:52:32 pi systemd[1]: Started go-librespot.service - go-librespot (open source Spotify client written in Go).
paź 25 19:52:32 pi go-librespot[9037]: time="2025-10-25T19:52:32+02:00" level=info msg="running go-librespot 2f3baebb"
paź 25 19:52:32 pi go-librespot[9037]: level=debug msg="app state loaded"
paź 25 19:52:32 pi go-librespot[9037]: level=info msg="api server listening on 192.168.1.3:3678"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]"
paź 25 19:52:33 pi go-librespot[9037]: level=info msg="zeroconf server listening on port 45787"
paź 25 19:52:33 pi go-librespot[9037]: level=info msg="loading previously persisted zeroconf credentials" username="sz**********nt"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="obtained new client token: AABkhePVOag5eWxFPO3tpFOlns8bWuQTYGHzbTlw6CaiIVm/+0+BNsknhnpTWGFxKwDPxf0ycDG7h+e++q8NU+CTwMHa10urQFxRQ8wdV7NuH5aZwM09PtJ4TIGl8S1qthmWJvkG0JNkXqwTYyXRWVni8haJHKgYOH5wJUcnx7AILjQKJD3Cf/Z6VPtvnFIL7k9UtoGFT0Ck5Xw4AO0nUJur8O1SSFvbjHfgs0/azA=="
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="connected to ap-gew4.spotify.com:4070"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="completed keyexchange"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="completed challenge"
paź 25 19:52:33 pi go-librespot[9037]: level=info msg="authenticated AP" username="sz**********nt"
paź 25 19:52:33 pi go-librespot[9037]: level=info msg="authenticated Login5" username="sz**********nt"
paź 25 19:52:33 pi go-librespot[9037]: level=debug msg="initializing zeroconf session" username="sz**********nt"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="dealer connection opened"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="received connection id: YmMzM2NhODEtOTBm...MjM5QkIxN0I1Rg=="
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="put connect state because NEW_DEVICE"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="update volume requested to 58981/65535"
paź 25 19:52:34 pi go-librespot[9037]: level=debug msg="put connect state because VOLUME_CHANGED"
paź 25 19:53:02 pi go-librespot[9037]: level=debug msg="handling transfer player command from 53fb062c7800a19dcec70de307dc66f9fa178620"
paź 25 19:53:02 pi go-librespot[9037]: level=debug msg="resolved context of track" uri="spotify:station:track:1ZEOIhSn6BKErV59bIgn76"
paź 25 19:53:02 pi go-librespot[9037]: level=debug msg="spclient request returned bad gateway, retrying..."
paź 25 19:53:10 pi go-librespot[9037]: level=debug msg="spclient request returned bad gateway, retrying..."
paź 25 19:53:28 pi go-librespot[9037]: level=debug msg="spclient request returned bad gateway, retrying..."
paź 25 19:53:32 pi go-librespot[9037]: level=error msg="failed fetching next tracks" error="failed moving to next index 50 ... spclient request failed: context deadline exceeded" uri="spotify:station:track:1ZEOIhSn6BKErV59bIgn76"
paź 25 19:53:32 pi go-librespot[9037]: level=debug msg="loading track (paused: true, position: 91860ms)" uri="spotify:track:2ctvdKmETyOzPb2GiJJT53"
paź 25 19:53:32 pi go-librespot[9037]: level=error msg="failed put state after update" error="context deadline exceeded"
paź 25 19:53:32 pi go-librespot[9037]: level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:2ctvdKmETyOzPb2GiJJT53: failed getting track metadata: spclient request failed: context deadline exceeded"

Any idea what might be wrong or how to debug this further?

[devgianlu]

This appears to be a combination of issues:

• Spotify returns 502 when trying to resolve the list of tracks associated with spotify:station:track:1ZEOIhSn6BKErV59bIgn76
• We retry 502 responses indefinitely
• The context for transfer requests expires and everything breaks

I am implementing some workarounds with #246, but I am not closing this. To debug further switch to the latest commit and increase the log level to trace. It should not fail to load anymore, just take ~10 seconds, but the logs should have a bit more insight.