no termination or reconnect on "connection reset error"

[JJ-Author]

Description
after a short internet interruption on provide side the new version 0.3.4 in contrast to 0.3.3 does not terminate but keeps running without being visible in spotfiy connect nor playing music (finished the cached song of course)

To Reproduce
play music
shortly unplug your WWAN of your internet router

Expected behavior
version 0.3.3 terminated so one could automatically restart the service with systemd. 0.3.4 does not succeed to reconnect and seems to be stuck in a somewhat useless state. it would be good to have the old behaviour back or that the main loop tries to reconnect in frequent intervals

Logs

● spotifyd.service - Spotifyd (DietPi)
     Loaded: loaded (/etc/systemd/system/spotifyd.service; disabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/spotifyd.service.d
             └─execStart.conf
     Active: active (running) since Wed 2022-12-28 18:52:22 CET; 4 days ago
   Main PID: 365 (spotifyd)
      Tasks: 2 (limit: 383)
        CPU: 1h 8min 33.899s
     CGroup: /system.slice/spotifyd.service
             └─365 /opt/spotifyd/spotifyd --no-daemon --config-path=/mnt/dietpi_userdata/spotifyd/spotifyd.conf

Jan 02 12:53:12 DietPi spotifyd[365]: Loading <When I'm Small> with Spotify URI <spotify:track:0PERS23jNsjcjBywXLvpyc>
Jan 02 12:53:12 DietPi spotifyd[365]: <When I'm Small> (249066 ms) loaded
Jan 02 12:57:21 DietPi spotifyd[365]: Loading <Young Blood> with Spotify URI <spotify:track:25nzKGDiua1lE9Qo5V19GL>
Jan 02 12:57:21 DietPi spotifyd[365]: <Young Blood> (246600 ms) loaded
Jan 02 13:01:28 DietPi spotifyd[365]: Loading <Héritage> with Spotify URI <spotify:track:4lxmHRfnm3YzESpIBeypft>
Jan 02 13:01:28 DietPi spotifyd[365]: <Héritage> (146053 ms) loaded
Jan 02 13:08:45 DietPi spotifyd[365]: Cannot flush spirc event sender.
Jan 02 13:08:45 DietPi spotifyd[365]: Unable to load audio item.
Jan 02 13:08:45 DietPi spotifyd[365]: Connecting to AP "ap.spotify.com:443"
Jan 02 13:08:46 DietPi spotifyd[365]: Connection reset by peer (os error 104)

Versions (please complete the following information):

• OS: DietPi 8.0.2
• Spotifyd: 0.3.4-armv6-slim

[JJ-Author]

interesting thing it seems not to happen every time when there is an internet connection issue. so sometimes it reconnects automatically but sometimes it gets stuck like in the example below

● spotifyd.service - Spotifyd (DietPi)
     Loaded: loaded (/etc/systemd/system/spotifyd.service; disabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/spotifyd.service.d
             └─execStart.conf
     Active: active (running) since Mon 2023-01-09 12:48:17 CET; 10h ago
   Main PID: 13067 (spotifyd)
      Tasks: 3 (limit: 383)
        CPU: 430ms
     CGroup: /system.slice/spotifyd.service
             └─13067 /opt/spotifyd/spotifyd --no-daemon --config-path=/mnt/dietpi_userdata/spotifyd/spotifyd.conf

Jan 09 12:48:17 DietPi spotifyd[13067]: Authenticated as "xxx" !
Jan 09 12:48:17 DietPi spotifyd[13067]: Country: "DE"
Jan 09 12:48:17 DietPi spotifyd[13067]: Using Alsa sink with format: S16
Jan 09 12:49:20 DietPi spotifyd[13067]: Connection reset by peer (os error 104)
Jan 09 12:49:20 DietPi spotifyd[13067]: subscription terminated
Jan 09 12:49:20 DietPi spotifyd[13067]: Connecting to AP "ap.spotify.com:443"
Jan 09 12:49:21 DietPi spotifyd[13067]: Authenticated as "xxx" !
Jan 09 12:49:21 DietPi spotifyd[13067]: Country: "DE"
Jan 09 12:49:21 DietPi spotifyd[13067]: Using Alsa sink with format: S16
Jan 09 12:53:31 DietPi spotifyd[13067]: Connection reset by peer (os error 104)

[JJ-Author]

for the record I post the internet connection log

-disconnected on: 2023-01-09T12:47:34,093646948+01:00
----connected on: 2023-01-09T12:48:12,713952948+01:00
-disconnected on: 2023-01-09T12:48:45,994556948+01:00
----connected on: 2023-01-09T12:49:20,843372948+01:00
-disconnected on: 2023-01-09T12:52:59,555321948+01:00
----connected on: 2023-01-09T12:53:31,871112948+01:00
-disconnected on: 2023-01-09T12:54:11,451712948+01:00
----connected on: 2023-01-09T12:54:17,627657948+01:00

[eladyn]

Thank you for the report! I'm not exactly sure, but that might have happened to me as well already. I hope, I'll find the time sometime soon to have a look at this, but it may also be that this would need changes in librespot and we can't do anything about it.

If you want, you could try running bare librespot and see, if the problem happens there as well. (I think, their reconnection logic is similar.) If you do, it would be great if you could report the results here.

[JJ-Author]

Thanks for the reply. I tried. But once I had a technician fixing my cable internet profile on the provider side I did not manage to reproduce the issue. It might be very timing sensitive since it only occured from time to time with my very unstable Internet connection (so in other words most of the reconnects worked). so maybe sth. like this: some packet loss, delayed packets or timeouts trigger the termination of the subscription, being back online triggers the reconnect, but while it is reconnecting the timeout is happening again).

[eladyn]

Oh, that's good to hear (although it makes it more difficult to debug the issue 😅). Thanks anyway for the pointers, where the issue might live. Maybe I can reproduce it reliably with these hints.

[aykevl]

Looks like I'm hitting a similar (if not identical) issue in #1211. Basically, even though my network is pretty stable it seems to terminate the Spotifyd connection after about 10 minutes. In my opinion, Spotifyd should try to reestablish the connection when that happens (maybe it needs to send some ping messages over the wire once in a while to keep it alive?).