librespot icon indicating copy to clipboard operation
librespot copied to clipboard

Client cannot connect to librespot

Open tonabnehmer opened this issue 9 months ago • 14 comments

Description

Can't connect to librespot. "spirc dealer" (librespot_core::dealer::manager] Launching dealer) seems stuck. resulting in an endless loop of re-connection attempts.

Version

What version(s) of librespot does this problem exist in? librespot 0.6.0-dev 837b3e6 (Built on 2025-03-31, Build ID: jRXFNQEP, Profile: release) build for raspberry pi 2

How to reproduce

Steps to reproduce the behavior in librespot e.g.

  1. Launch librespot with system/systemd service: "/usr/bin/librespot --v --cache /var/lib/private/librespot --name raspberry --device sysdefault:CARD=sndrphifiberry --bitrate 320"
  2. Connect with any device
  3. In the client click on connect
  4. Client can't connect. Resulting in connection attempts.

Log

https://pastebin.com/rrgtCScv

Host (what you are running librespot on):

  • OS: Raspbian 12; 6.6.51+rpt-rpi-v7
  • Platform: rpi-2, hifiberry plus dac

Additional context

Retried with clean cache, retried oauth

tonabnehmer avatar Mar 31 '25 14:03 tonabnehmer

Just to clear some things up, we are talking about an unauthenticated librespot "device" which we then transfer the playback to via an official client or api, right?

Could you also try to run librespot as cli application, not as systemd service, and see if that makes a difference?

photovoltex avatar Mar 31 '25 15:03 photovoltex

No, it's authenticated with Oauth. I'm sorry if I was unclear. I tried running it from cli as well. Same results. But if you want, I can upload those logs as well. They look similar to me.

tonabnehmer avatar Mar 31 '25 16:03 tonabnehmer

I'm just trying to understand the situation a bit more clearly to get all the info's we might need to reproduce, fix it or help you resolve it.

For myself it seems to work fine. I tried zeroconf, oauth and cached login/startup and all seem to be fine.

Have you used librespot before and if yes, did this just happened recently? Do you have a special network setup? How did you compile your binary? And do you have a different device to maybe check if it would work there?

Thanks in advance for all the info^^

photovoltex avatar Mar 31 '25 17:03 photovoltex

Sure, here is some more information,

  • recently re-setup my pi, with newest raspbian
  • worked fine until just a few days ago
  • compiled new version, hoping it would resolve my issues
  • when this did not help, switched from user/systemd to system/systemd
  • tried running it from cli
  • cleared cache, tried different directory locations - just in case
  • re-did oauth
  • network setup is straight forward, pi connected to my router via ethernet, network seems to be working fine (see also log that states that it can connect to spotify AP)
  • compiled with cross-compile docker
  • I don't have a different raspberry system lying around, so can't test it with any other ARM device...

hope this helps.

tonabnehmer avatar Mar 31 '25 19:03 tonabnehmer

So this is getting weird, after leaving it unattended for a couple of days, the 'dealer' seems to be able to start: (grep for librespot_connect::spirc)

Mar 31 18:39:12 raspberrypi librespot[2367]: [2025-03-31T16:39:12Z DEBUG librespot_connect::spirc] drop Spirc[65]
Mar 31 18:39:12 raspberrypi librespot[2367]: [2025-03-31T16:39:12Z DEBUG librespot_connect::spirc] new Spirc[66]
Mar 31 18:41:31 raspberrypi librespot[2367]: [2025-03-31T16:41:31Z ERROR librespot_connect::spirc] starting dealer failed: Invalid state { Websocket couldn't be started because: Deadline expired before operation could complete { Connection timed out (os error 110) } }
Mar 31 18:41:31 raspberrypi librespot[2367]: [2025-03-31T16:41:31Z DEBUG librespot_connect::spirc] drop Spirc[66]
Mar 31 18:41:31 raspberrypi librespot[2367]: [2025-03-31T16:41:31Z DEBUG librespot_connect::spirc] new Spirc[67]
Mar 31 18:43:49 raspberrypi librespot[2367]: [2025-03-31T16:43:49Z ERROR librespot_connect::spirc] starting dealer failed: Invalid state { Websocket couldn't be started because: Deadline expired before operation could complete { Connection timed out (os error 110) } }
Mar 31 18:43:49 raspberrypi librespot[2367]: [2025-03-31T16:43:49Z DEBUG librespot_connect::spirc] drop Spirc[67]
Mar 31 18:43:49 raspberrypi librespot[2367]: [2025-03-31T16:43:49Z DEBUG librespot_connect::spirc] new Spirc[68]
Mar 31 18:43:50 raspberrypi librespot[2367]: [2025-03-31T16:43:50Z TRACE librespot_connect::spirc] Received connection ID update: "YWFlZWVkN2EtYjE1MS00MDE5LThiZDctMDkwMGE4Y2I3ZmJmK2RlYWxlcit0Y3A6Ly8wYWNhNWE0YS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDJCRENENTM4N0I5MDAzMkE2RTk5MkQ1NjlEQkQ2RTBGMURERUQxRjEyRjg3MTMxN0Y4Nzg3QUI1MzYxRjJDQg=="
Mar 31 18:43:50 raspberrypi librespot[2367]: [2025-03-31T16:43:50Z DEBUG librespot_connect::spirc] successfully put connect state for eaca980117c022577f5b2fdce33242bd13148447 with connection-id YWFlZWVkN2EtYjE1MS00MDE5LThiZDctMDkwMGE4Y2I3ZmJmK2RlYWxlcit0Y3A6Ly8wYWNhNWE0YS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDJCRENENTM4N0I5MDAzMkE2RTk5MkQ1NjlEQkQ2RTBGMURERUQxRjEyRjg3MTMxN0Y4Nzg3QUI1MzYxRjJDQg==
Mar 31 18:43:50 raspberrypi librespot[2367]: [2025-03-31T16:43:50Z INFO  librespot_connect::spirc] active device is <> with session <5wCuFAQoIWvtreiDWi92hK>

Restarting works as well. I have not changed anything since I created the ticket. Any idea how to further debug this?

tonabnehmer avatar Apr 02 '25 08:04 tonabnehmer

Yesterday I had the same (probably) issue. RPI was visible as an external speaker but I could not connect to it. Today everything works fine...

The only thing that was strange to me was that yesterday I could not ping spotify.com from my RPI using IPv4 (only with IPv6), today both pings are working.

pkantor avatar Apr 02 '25 08:04 pkantor

Hmm, how did both of you compile the binary? There was a similarly sounding issue here which was related to the compiler/system #1437. So maybe that might be related?

photovoltex avatar Apr 03 '25 05:04 photovoltex

I don't think this looks like that armlogic compiler issue, things are getting much further and they're using different hardware and different OS. This looks more like a transient network problem to me.

kingosticks avatar Apr 03 '25 06:04 kingosticks

cat /proc/version Linux version 6.6.28+rpt-rpi-v8 ([email protected]) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT Debian 1:6.6.28-1+rpt1 (2024-04-22)

uname -m Linux raspberrypi 6.6.28+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.28-1+rpt1 (2024-04-22) aarch64 GNU/Linux

I build with cargo install --git https://github.com/librespot-org/librespot --branch dev --no-default-features --features alsa-backend,with-libmdns --target-dir /home/user/librespot/compiled --root /home/user/librespot/root

Then i run as service /usr/bin/librespot -n "MySpeaker" -b 320 --enable-volume-normalisation --normalisation-pregain 0 --initial-volume 69 --autoplay on

pkantor avatar Apr 03 '25 06:04 pkantor

I don't think this looks like that armlogic compiler issue, things are getting much further and they're using different hardware and different OS. This looks more like a transient network problem to me.

Network problems on the machine itself? Or handling within librespot? I can say that I noticed some IPv4/6 problems with my system as well, but have not checked for spotify.com connectivity. Will monitor.

For good measure, I build with cross-compile docker on my Fedora 41 machine:

docker run -v /tmp/librespot-build:/build:Z librespot-cross cargo build --release --target arm-unknown-linux-gnueabihf --no-default-features --features alsa-backend,with-libmdns

tonabnehmer avatar Apr 03 '25 12:04 tonabnehmer

I don't know, I would guess problems with Spotify's network given that you changed nothing to make it work.

kingosticks avatar Apr 03 '25 13:04 kingosticks

For some further examples, I'm seeing a similar thing in my setup which has been successfully long running, although I did reboot the machine yesterday, and add pulseaudio back to the system, however I think these are unrelated. I am using librespot through snapcast, I am using it like

an unauthenticated librespot "device" which we then transfer the playback to via an official client or api snapcast uses the pipe backend to stdout as a systemd service using a snapcast user.

I've tried CLI direct calling librespot, running as different users, and different cache settings. Interestingly I could get CLI to stdout to work running as root for a time but it isn't as of typing this, So I initially assumed that there was something wrong with my set up to do with running as a service or as the snapcast user. But I think given this thread that it's maybe at the spotify end, I also see the AP timeouts similar to those mentioned by issue https://github.com/librespot-org/librespot/issues/1477.

As per this issue I've made sure to force ipv4 connections and will monitor over the next few days hoping to see it come right. I guess all this suggests something changing on the Spotify side (perhaps related to something they're doing around this https://github.com/librespot-org/librespot/issues/1465).

sierra-alpha avatar Apr 05 '25 19:04 sierra-alpha

Mine never managed to reconnect but I did find this issue (https://github.com/librespot-org/librespot/issues/1490 added after my comment above) is exactly my problem.

sierra-alpha avatar May 03 '25 09:05 sierra-alpha

I encountered the same error of:

[ERROR] starting dealer failed: Invalid state { Websocket couldn't be started because: Deadline expired before operation could complete { Connection timed out (os error 110) } }

The issue was with my networking setup. My computer is on an ipv6 network, but I am using wireguard to vpn into a network that only supports ipv4. For some reason, my dns is resolved the ipv6 address for spotify.com when I tried pinging, meaning I am not able to access it. The problem disappeared after disconnecting my VPN, as I was able to access the ipv6 internet again.

tldr: it seems to be caused by spotify.com not being accessible over the network

VoidAny avatar Nov 12 '25 05:11 VoidAny