librespot (Spotify Connect) Failing With "NetworkUnreachable"

[chanthing]

Greetings,

I'm working with the Spotify Renderer in Moode 8.2.5 with version 0.4.2 of librespot. 

After a fresh start of the Pi, the associated Spotify connect device shows up in the Spotify App menu as an option. I can select it and start streaming successfully.

However, after around ten minutes or so, the renderer disconnects from Spotify and I no longer see it as an option in the app. By starting librespot manually and capturing stderr and stdout, I am able to see that the error that chokes it looks like
--------
[2023-02-20T23:00:52Z WARN  libmdns::fsm] error sending packet Os { code: 101, kind: NetworkUnreachable, message: "Network is unreachable" }

[2023-02-20T23:01:15Z DEBUG librespot_playback::player] command=Preload(SpotifyId { id: 278088895657592380805861049375931454054, audio_type: Track })
[2023-02-20T23:01:15Z DEBUG librespot_playback::player] Preloading track
[2023-02-20T23:01:45Z DEBUG librespot_connect:pirc] At track 7 of 50 <"spotify:playlist:37i9dQZF1DWUKTqLl4oNGg"> update [false]
[2023-02-20T23:01:45Z TRACE librespot_connect:pirc] Sending status to server: [kPlayStatusPlay]
[2023-02-20T23:01:45Z DEBUG librespot_playback::player] command=Load(SpotifyId { id: 278088895657592380805861049375931454054, audio_type: Track }, true, 0)
[2023-02-20T23:01:45Z TRACE librespot_playback::player] == Stopping sink ==
[2023-02-20T23:01:45Z TRACE librespot_connect:pirc] Sending status to server: [kPlayStatusPlay]
^C[2023-02-20T23:04:39Z INFO  librespot] Gracefully shutting down
[2023-02-20T23:04:39Z DEBUG librespot_playback::player] command=Stop
------

If I then kill librespot and attempt to start it again, I get these messages
-------
[2023-02-20T23:05:01Z INFO  librespot] librespot 0.4.2 22f8aed (Built on 2022-08-18, Build ID: LQ4hikXT, Profile: release)
[2023-02-20T23:05:01Z TRACE librespot] Command line argument(s):
[2023-02-20T23:05:01Z TRACE librespot] name "SpotifyTest"
[2023-02-20T23:05:01Z TRACE librespot] v
[2023-02-20T23:05:01Z DEBUG librespot_discovery:erver] Zeroconf server listening on 0.0.0.0:33665
[2023-02-20T23:05:01Z WARN  librespot] Could not initialise discovery: Setting up dns-sd failed: No such device (os error 19).
[2023-02-20T23:05:01Z ERROR librespot] Discovery is unavailable and no credentials provided. Authentication is not possible.
------

Any ideas? In reading other threads, it seems like the 0.5 version of librespot may offer some relief. Is that possible to use with moode by loading the package? Where might I find that package?

Any advice greatly appreciated.

-- Thing

[Tim Curtis]

Latest release is 0.4.2
https://github.com/librespot-org/libresp...tag/v0.4.2

[chanthing]

Latest release is 0.4.2
https://github.com/librespot-org/libresp...tag/v0.4.2

Thanks. In another thread on this forum, a version 0.5.0 was mentioned. I had looked in github and didn't see it. Hence my question.

Any thoughts about what might be going on?

I'm particularly curious about why it's not possible to restart librespot after this happens, without rebooting the system.

Thanks!

[TheOldPresbyope]

@chanthing 

Curious. Nothing similar happening here.

My test article: moOde 8.2.5 on a Pi4B with I2S HiFi Berry DAC+ Pro HAT driving a headphone amp connected to headphones. This player is connected to my LAN router/AP via WiFi.

I started the Spotify app on my iPad at 730AM and connected to the moOde player (via Spotify Connect built into the app, not via Bluetooth or ApplePlay). I've been listening to this setup on and off for 5 hours now. It continues to play tracks from the Spotify-curated playlists I selected and the moOde player continues to show up in the "Select a device" list in the Spotify app.

That "network is unreachable" message suggests something is happening elsewhere in your system and causing librespot to fail because of the services it depends on (apparently MDNS in this case). I could be wrong, of course, but unless I can repro your results I can't go any further.

Regards,
Kent

[chanthing]

@chanthing 

Curious. Nothing similar happening here.

My test article: moOde 8.2.5 on a Pi4B with I2S HiFi Berry DAC+ Pro HAT driving a headphone amp connected to headphones. This player is connected to my LAN router/AP via WiFi.

I started the Spotify app on my iPad at 730AM and connected to the moOde player (via Spotify Connect built into the app, not via Bluetooth or ApplePlay). I've been listening to this setup on and off for 5 hours now. It continues to play tracks from the Spotify-curated playlists I selected and the moOde player continues to show up in the "Select a device" list in the Spotify app.

That "network is unreachable" message suggests something is happening elsewhere in your system and causing librespot to fail because of the services it depends on (apparently MDNS in this case). I could be wrong, of course, but unless I can repro your results I can't go any further.

Regards,
Kent

Thanks very much for the reply. I'm trying now with ethernet rather than wifi. Your config is very similar to mine, so it's good to hear that it *should* work. I'll post any relevant findings here.

[chanthing]

QQ: How can I run librespot as a moode renderer and get debug output somewhere where I can examine it after the fact?

[Tim Curtis]

QQ: How can I run librespot as a moode renderer and get debug output somewhere where I can examine it after the fact?

1. sudo nano /var/www/inc/renderer.php

2. Page down to function startSpotify()

3. Near the end of the function you will see the two lines below. Comment out the first line and un-comment the second line.

Original

Code:

' > /dev/null 2>&1 &';
//' -v > /home/pi/librespot.txt 2>&1 &'; // For debug

Modified 

Code:

//' > /dev/null 2>&1 &';
' -v > /home/pi/librespot.txt 2>&1 &'; // For debug

4. Save the edit 
5. Open Renderer Config and restart Spotify Connect
6. The log will be /home/pi/librespot.txt

[chanthing]

Thanks very much for the troubleshooting info. I tried running with a static IP and that seemed to help. However, what ends up seeming to happen is that for some reason, the wireless connection loses its IPV4 information. After I started seeing the NetworkUnreachable error, I did an ifconfig and here's what I see for my wireless connection

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

        inet6 fe80::df87:b801:a8:5a69  prefixlen 64  scopeid 0x20<link>
        ether e4:5f:01:e6:07:48  txqueuelen 1000  (Ethernet)
        RX packets 97485  bytes 99865071 (95.2 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 37143  bytes 11967105 (11.4 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

For some reason, wlan0 is no longer has an inet entry associated with its address. 

daemon.log has these interesting entries:

Feb 21 22:59:12 savagemusic winbindd[559]: [2023/02/21 22:59:12.343316,  0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)

Feb 21 22:59:12 savagemusic winbindd[559]:   rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Feb 21 22:59:44 savagemusic dhcpcd[892]: wlan0: hardware address 00:00:00:00:00:00 claims 192.168.1.85
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: hardware address 00:00:00:00:00:00 claims 192.168.1.85
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: 10 second defence failed for 192.168.1.85
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Withdrawing address record for 192.168.1.85 on wlan0.
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.85.
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Interface wlan0.IPv4 no longer relevant for mDNS.
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: deleting route to 192.168.1.0/24
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: deleting default route via 192.168.1.1

FWIW, the RPC error happens a bunch before this sequence removing the address record and the and the route are removed. I included it for completeness, but I don't think it's related. 

Any insights on what might be causing this are welcome. If I haven't exited my ssh connection, I can restart dhcpcd and everything is cool, but why is it bailing?

[Obviously this affects more than just librespot]

[chanthing]

Thanks very much for the troubleshooting info. I tried running with a static IP and that seemed to help. However, what ends up seeming to happen is that for some reason, the wireless connection loses its IPV4 information. After I started seeing the NetworkUnreachable error, I did an ifconfig and here's what I see for my wireless connection

wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500

        inet6 fe80::df87:b801:a8:5a69  prefixlen 64  scopeid 0x20<link>
        ether e4:5f:01:e6:07:48  txqueuelen 1000  (Ethernet)
        RX packets 97485  bytes 99865071 (95.2 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 37143  bytes 11967105 (11.4 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

For some reason, wlan0 is no longer has an inet entry associated with its address. 

daemon.log has these interesting entries:

Feb 21 22:59:12 savagemusic winbindd[559]: [2023/02/21 22:59:12.343316,  0] ../../source3/rpc_server/rpc_ncacn_np.c:454(rpcint_dispatch)

Feb 21 22:59:12 savagemusic winbindd[559]:   rpcint_dispatch: DCE/RPC fault in call lsarpc:32 - DCERPC_NCA_S_OP_RNG_ERROR
Feb 21 22:59:44 savagemusic dhcpcd[892]: wlan0: hardware address 00:00:00:00:00:00 claims 192.168.1.85
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: hardware address 00:00:00:00:00:00 claims 192.168.1.85
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: 10 second defence failed for 192.168.1.85
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Withdrawing address record for 192.168.1.85 on wlan0.
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.85.
Feb 21 22:59:46 savagemusic avahi-daemon[405]: Interface wlan0.IPv4 no longer relevant for mDNS.
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: deleting route to 192.168.1.0/24
Feb 21 22:59:46 savagemusic dhcpcd[892]: wlan0: deleting default route via 192.168.1.1

FWIW, the RPC error happens a bunch before this sequence removing the address record and the and the route are removed. I included it for completeness, but I don't think it's related. 

Any insights on what might be causing this are welcome. If I haven't exited my ssh connection, I can restart dhcpcd and everything is cool, but why is it bailing?

[Obviously this affects more than just librespot]

FWIW, my router's dhcp is configured to only hand out addresses higher than 192.168.1.100. But I have some cheap LED bulbs that connect via wireless. Could they be trying to grab that IP?

[Tim Curtis]

The symptom "for some reason, the wireless connection loses its IPV4 information" suggests a hardware or network issue external to moOde software.