raspotify stops being available on the network (presumably after crashing)
blubbafett opened this issue · 23 comments
Compatible Device
- I'm running Raspotify on a compatible Device
Are you sure?
- I'm not trying to run Raspotify on a ARMv6 device
Compatible OS
- I'm running Raspotify on a compatible OS
Compatible Configuration
- I'm running Raspotify on a compatible Configuration
Latest Version
- I'm running the latest version of Raspotify
Are you sure?
- I'm not running Raspotify 0.31.8.1 on a on a Pi v1 or Pi Zero
Due Diligence
- I have done my due diligence
What happened?
Experiencing that raspotify stops being available on the network, to both my and my better half's frustration, (who isn't tech-savy and know how to restart the service through ssh'ing into the rpi. :p)
She complained about not finding the device under devices in her Spotify app. When I ssh'ed into the rpi and checked the status for the systemd service this was the output:
pi@raspberrypi: $ sudo systemctl status raspotify.service
● raspotify.service - Raspotify (Spotify Connect Client)
Loaded: loaded (/lib/systemd/system/raspotify.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2022-09-05 23:26:36 CEST; 1 weeks 4 days ago
Docs: https://github.com/dtcooper/raspotify
https://github.com/librespot-org/librespot
https://github.com/dtcooper/raspotify/wiki
https://github.com/librespot-org/librespot/wiki/Options
Main PID: 644 (librespot)
Tasks: 1 (limit: 780)
CPU: 1.900s
CGroup: /system.slice/raspotify.service
└─644 /usr/bin/librespotSep 09 02:32:42 raspberrypi librespot[644]: 40: 0x557e227bb0 - std::panic::catch_unwind::h1f317b68a309cc71
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0>Sep 09 02:32:42 raspberrypi librespot[644]: 41: 0x557e227bb0 - std::rt::lang_start_internal::hfb3b3ed4bb8bd7fd
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0>Sep 09 02:32:42 raspberrypi librespot[644]: 42: 0x557dea0e28 - main
Sep 09 02:32:43 raspberrypi librespot[644]: 43: 0x7f936912fc - __libc_start_call_main
Sep 09 02:32:43 raspberrypi librespot[644]: at ./csu/../sysdeps/nptl/libc_start_call_mai>Sep 09 02:32:43 raspberrypi librespot[644]: 44: 0x7f936913cc - __libc_start_main_impl
Sep 09 02:32:43 raspberrypi librespot[644]: at ./csu/../csu/libc-start.c:389:3
Sep 09 02:32:43 raspberrypi librespot[644]: 45: 0x557de1a64c -
lines 1-23/23 (END)
Although it said Active: active (running) it wasn't possible to connect to the device, neither from my own mobile nor my gf's. It reporting "active" is the reason I used presumably in the title,.
Doing a restart of the service fixed the issue, however, it'd be nice to not having to face these errors in the future, as it's not always I'm around to do a restart whenver my gf wants to use the device.
I guess it'll be a librespot issue in the end, but it's affecting raspotify, at least on my device..
Running latest raspotify version on a rpi 3b+ (Raspberry Pi 3 Model B Plus Rev 1.3 from cat /proc/cpuinfo). The device is connected to the network with an ethernet cable, wifi and on-board bluetooth are both disabled, if that should matter for this issue.
pi@raspberrypi: $ apt show raspotify
Package: raspotify
Version: 0.42.4 librespot.v0.4.2-6537c44
Priority: optional
Section: base
Maintainer: Jason Gray jasonlevigray3@gmail.com
Installed-Size: unknown
Depends: libc6 (>= 2.31), libasound2 (>= 1.2.4), alsa-utils (>= 1.2.4), libpulse0 (>= 14.2), systemd (>= 247.3), init-system-helpers (>= 1.60)
Homepage: https://github.com/dtcooper/raspotify
Download-Size: 2,834 kB
APT-Manual-Installed: yes
APT-Sources: https://dtcooper.github.io/raspotify raspotify/main arm64 Packages
Description: Raspotify
A Spotify Connect systemd daemon for Debian Stable based headless systems which thinly wraps librespot.
[Built with rustc 1.63.0 (4b91a6ea7 2022-08-08)]
pi@raspberrypi:~ $ uname -a
Linux raspberrypi 5.15.32-v8+ #1538 SMP PREEMPT Thu Mar 31 19:40:39 BST 2022 aarch64 GNU/Linux
Not sure what other logs you might need except the output from journalctl, which I've pasted in the relevant log output. If anything more is needed / etc, just yell out and I'll do my best to provide it. NB; I've edited out the ip address of the device from the logs.
Relevant log output
-- Journal begins at Mon 2022-04-04 16:41:41 CEST, ends at Fri 2022-09-16 23:35:09 CEST. --
Sep 04 22:56:37 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 04 23:01:28 raspberrypi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Sep 04 23:01:28 raspberrypi systemd[1]: raspotify.service: Succeeded.
Sep 04 23:01:28 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 04 23:01:28 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 04 23:01:48 raspberrypi librespot[1291]: [2022-09-04T21:01:48Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Sep 04 23:01:48 raspberrypi librespot[1291]: [2022-09-04T21:01:48Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Sep 04 23:01:48 raspberrypi librespot[1291]: [2022-09-04T21:01:48Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Sep 04 23:01:48 raspberrypi librespot[1291]: [2022-09-04T21:01:48Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
Sep 04 23:02:15 raspberrypi librespot[1291]: [2022-09-04T21:02:15Z WARN librespot_playback::audio_backend::alsa] Error writing from AlsaSink buffer to PCM, trying to recover, ALSA function >
Sep 04 23:02:15 raspberrypi librespot[1291]: ALSA lib pcm.c:8545:(snd_pcm_recover) underrun occurred
Sep 05 04:48:48 raspberrypi librespot[1291]: [2022-09-05T02:48:48Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: label in domain name has unknown label format
Sep 05 05:01:25 raspberrypi librespot[1291]: [2022-09-05T03:01:25Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 05:21:54 raspberrypi librespot[1291]: [2022-09-05T03:21:54Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 09:55:24 raspberrypi librespot[1291]: [2022-09-05T07:55:24Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 13:44:37 raspberrypi librespot[1291]: [2022-09-05T11:44:37Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 13:51:32 raspberrypi librespot[1291]: [2022-09-05T11:51:32Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 15:51:50 raspberrypi librespot[1291]: [2022-09-05T13:51:50Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 16:52:28 raspberrypi librespot[1291]: [2022-09-05T14:52:28Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 17:12:53 raspberrypi librespot[1291]: [2022-09-05T15:12:53Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 17:30:34 raspberrypi librespot[1291]: [2022-09-05T15:30:34Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 22:02:48 raspberrypi librespot[1291]: [2022-09-05T20:02:48Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 22:19:35 raspberrypi librespot[1291]: [2022-09-05T20:19:35Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Sep 05 22:19:35 raspberrypi librespot[1291]: [2022-09-05T20:19:35Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Sep 05 22:19:35 raspberrypi librespot[1291]: [2022-09-05T20:19:35Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Sep 05 22:19:35 raspberrypi librespot[1291]: [2022-09-05T20:19:35Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Sep 05 22:19:56 raspberrypi librespot[1291]: [2022-09-05T20:19:56Z WARN librespot_playback::player] Player::pause called from invalid state
Sep 05 22:26:28 raspberrypi librespot[1291]: [2022-09-05T20:26:28Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 22:32:11 raspberrypi librespot[1291]: [2022-09-05T20:32:11Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 23:18:43 raspberrypi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Sep 05 23:18:43 raspberrypi systemd[1]: raspotify.service: Succeeded.
Sep 05 23:18:43 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 05 23:18:43 raspberrypi systemd[1]: raspotify.service: Consumed 1min 1ms CPU time.
-- Boot a16f918d8ae74b06aa401357ccbfed30 --
Sep 05 23:18:48 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 05 23:18:49 raspberrypi librespot[466]: [2022-09-05T21:18:49Z WARN librespot] Could not initialise discovery: Setting up dns-sd failed: No such device (os error 19).
Sep 05 23:18:49 raspberrypi librespot[466]: [2022-09-05T21:18:49Z ERROR librespot] Discovery is unavailable and no credentials provided. Authentication is not possible.
Sep 05 23:18:49 raspberrypi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Sep 05 23:18:49 raspberrypi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Sep 05 23:19:15 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 1.
Sep 05 23:19:15 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 05 23:19:15 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 05 23:23:22 raspberrypi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Sep 05 23:23:22 raspberrypi systemd[1]: raspotify.service: Succeeded.
Sep 05 23:23:22 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
-- Boot d3c5818f8b694d8eb19345f8ac03c044 --
Sep 05 23:23:27 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 05 23:23:28 raspberrypi librespot[466]: [2022-09-05T21:23:28Z WARN librespot] Could not initialise discovery: Setting up dns-sd failed: No such device (os error 19).
Sep 05 23:23:28 raspberrypi librespot[466]: [2022-09-05T21:23:28Z ERROR librespot] Discovery is unavailable and no credentials provided. Authentication is not possible.
Sep 05 23:23:28 raspberrypi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Sep 05 23:23:28 raspberrypi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Sep 05 23:23:54 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 1.
Sep 05 23:23:54 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 05 23:23:54 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 05 23:25:22 raspberrypi librespot[623]: [2022-09-05T21:25:22Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 05 23:26:04 raspberrypi systemd[1]: Stopping Raspotify (Spotify Connect Client)...
Sep 05 23:26:05 raspberrypi systemd[1]: raspotify.service: Succeeded.
Sep 05 23:26:05 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
-- Boot 1195ab265a4e4b16a2621b70ec5d745b --
Sep 05 23:26:10 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 05 23:26:11 raspberrypi librespot[469]: [2022-09-05T21:26:11Z WARN librespot] Could not initialise discovery: Setting up dns-sd failed: No such device (os error 19).
Sep 05 23:26:11 raspberrypi librespot[469]: [2022-09-05T21:26:11Z ERROR librespot] Discovery is unavailable and no credentials provided. Authentication is not possible.
Sep 05 23:26:11 raspberrypi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Sep 05 23:26:11 raspberrypi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Sep 05 23:26:36 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 1.
Sep 05 23:26:36 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 05 23:26:36 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 06 00:30:38 raspberrypi librespot[644]: [2022-09-05T22:30:38Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 06 09:23:54 raspberrypi librespot[644]: [2022-09-06T07:23:54Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 06 15:12:09 raspberrypi librespot[644]: [2022-09-06T13:12:09Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: label in domain name has unknown label format
Sep 06 17:46:57 raspberrypi librespot[644]: [2022-09-06T15:46:57Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 06 18:11:18 raspberrypi librespot[644]: [2022-09-06T16:11:18Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 06 20:21:34 raspberrypi librespot[644]: [2022-09-06T18:21:34Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 07 03:38:03 raspberrypi librespot[644]: [2022-09-07T01:38:03Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet is smaller than header size
Sep 07 09:24:04 raspberrypi librespot[644]: [2022-09-07T07:24:04Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 07 20:56:40 raspberrypi librespot[644]: [2022-09-07T18:56:40Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 08 01:32:44 raspberrypi librespot[644]: [2022-09-07T23:32:44Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 08 02:12:21 raspberrypi librespot[644]: [2022-09-08T00:12:21Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 08 02:29:22 raspberrypi librespot[644]: [2022-09-08T00:29:22Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet is has incomplete data
Sep 08 03:31:53 raspberrypi librespot[644]: [2022-09-08T01:31:53Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 08 20:15:49 raspberrypi librespot[644]: [2022-09-08T18:15:49Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 09 02:16:34 raspberrypi librespot[644]: [2022-09-09T00:16:34Z WARN libmdns::fsm] couldn't parse packet from <removed from log>: packet has non-zero reserved bits
Sep 09 02:32:42 raspberrypi librespot[644]: thread 'main' panicked at 'range end index 43 out of range for slice of length 32', library/core/src/slice/index.rs:73:5
Sep 09 02:32:42 raspberrypi librespot[644]: stack backtrace:
Sep 09 02:32:42 raspberrypi librespot[644]: 0: 0x557e233d64 - std::backtrace_rs::backtrace::libunwind::trace::hdaf7b926686b76e5
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
Sep 09 02:32:42 raspberrypi librespot[644]: 1: 0x557e233d64 - std::backtrace_rs::backtrace::trace_unsynchronized::h24b637dca55f9a5e
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
Sep 09 02:32:42 raspberrypi librespot[644]: 2: 0x557e233d64 - std::sys_common::backtrace::_print_fmt::h4cb8409104309785
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys_common/backtrace.rs:66:5
Sep 09 02:32:42 raspberrypi librespot[644]: 3: 0x557e233d64 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hc4ec9cb9b20b5a7b
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys_common/backtrace.rs:45:22
Sep 09 02:32:42 raspberrypi librespot[644]: 4: 0x557e256088 - core::fmt::write::h2322d71f3fb268fc
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/fmt/mod.rs:1197:17
Sep 09 02:32:42 raspberrypi librespot[644]: 5: 0x557e22e730 - std::io::Write::write_fmt::hc0c6b55df7cbd64b
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/io/mod.rs:1672:15
Sep 09 02:32:42 raspberrypi librespot[644]: 6: 0x557e235574 - std::sys_common::backtrace::_print::h446ed48475d9d586
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys_common/backtrace.rs:48:5
Sep 09 02:32:42 raspberrypi librespot[644]: 7: 0x557e235574 - std::sys_common::backtrace::print::h9b9a1d50fa9ea120
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys_common/backtrace.rs:35:9
Sep 09 02:32:42 raspberrypi librespot[644]: 8: 0x557e235574 - std::panicking::default_hook::{{closure}}::ha6c2222df3379e34
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:295:22
Sep 09 02:32:42 raspberrypi librespot[644]: 9: 0x557e2352c8 - std::panicking::default_hook::hfce7a8f7bcbba82f
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:314:9
Sep 09 02:32:42 raspberrypi librespot[644]: 10: 0x557e235ac0 - std::panicking::rust_panic_with_hook::h90a858afb3dbe829
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:698:17
Sep 09 02:32:42 raspberrypi librespot[644]: 11: 0x557e2359a8 - std::panicking::begin_panic_handler::{{closure}}::h882ab86c0d7c5158
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:588:13
Sep 09 02:32:42 raspberrypi librespot[644]: 12: 0x557e23420c - std::sys_common::backtrace::__rust_end_short_backtrace::hbcab7df1db34555f
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/sys_common/backtrace.rs:138:18
Sep 09 02:32:42 raspberrypi librespot[644]: 13: 0x557e2356f4 - rust_begin_unwind
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:584:5
Sep 09 02:32:42 raspberrypi librespot[644]: 14: 0x557de1a444 - core::panicking::panic_fmt::h58c4ca31339ea3fd
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/panicking.rs:142:14
Sep 09 02:32:42 raspberrypi librespot[644]: 15: 0x557e2579a8 - core::slice::index::slice_end_index_len_fail_rt::h33ab4ad148b3bd7c
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/slice/index.rs:73:5
Sep 09 02:32:42 raspberrypi librespot[644]: 16: 0x557e24f6e4 - core::ops::function::FnOnce::call_once::h414d23a4fece967d
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/ops/function.rs:248:5
Sep 09 02:32:42 raspberrypi librespot[644]: 17: 0x557e253440 - core::intrinsics::const_eval_select::h216e27a34f4a8c41
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/intrinsics.rs:2376:5
Sep 09 02:32:42 raspberrypi librespot[644]: 18: 0x557de1a500 - core::slice::index::slice_end_index_len_fail::h208127364579b5dc
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/slice/index.rs:67:9
Sep 09 02:32:42 raspberrypi librespot[644]: 19: 0x557df36cf0 - libmdns::dns_parser::name::Name::scan::heb8881e2b14c7219
Sep 09 02:32:42 raspberrypi librespot[644]: 20: 0x557df2db98 - libmdns::dns_parser::parser::<impl libmdns::dns_parser::structs::Packet>::parse::h8c485ed8985edeb7
Sep 09 02:32:42 raspberrypi librespot[644]: 21: 0x557df3b2ec - <libmdns::fsm::FSM<AF> as core::future::future::Future>::poll::hc5df1f4ddcec15c3
Sep 09 02:32:42 raspberrypi librespot[644]: 22: 0x557df3de9c - <futures_util::future::join::Join<Fut1,Fut2> as core::future::future::Future>::poll::h630e2002e9d84084
Sep 09 02:32:42 raspberrypi librespot[644]: 23: 0x557df2fac0 - <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll::ha39fdf4048e7a142
Sep 09 02:32:42 raspberrypi librespot[644]: 24: 0x557df3d624 - tokio::runtime::task::harness::Harness<T,S>::poll::ha5ca22e813a6d8e6
Sep 09 02:32:42 raspberrypi librespot[644]: 25: 0x557deb99c4 - std::thread::local::LocalKey<T>::with::h43531fd33fc4db63
Sep 09 02:32:42 raspberrypi librespot[644]: 26: 0x557de80d30 - tokio::runtime::basic_scheduler::Context::run_task::h4fb0a589b31c7def
Sep 09 02:32:42 raspberrypi librespot[644]: 27: 0x557dec5204 - tokio::macros::scoped_tls::ScopedKey<T>::set::h5854365682fce3bd
Sep 09 02:32:42 raspberrypi librespot[644]: 28: 0x557de808fc - tokio::runtime::basic_scheduler::BasicScheduler::block_on::hae970da3c0b8ac36
Sep 09 02:32:42 raspberrypi librespot[644]: 29: 0x557dec618c - tokio::runtime::Runtime::block_on::hecf8445bdca8df58
Sep 09 02:32:42 raspberrypi librespot[644]: 30: 0x557dea0d4c - librespot::main::h32cf1b934d0bd235
Sep 09 02:32:42 raspberrypi librespot[644]: 31: 0x557deb9960 - std::sys_common::backtrace::__rust_begin_short_backtrace::hf1bf5bc23dde1c5e
Sep 09 02:32:42 raspberrypi librespot[644]: 32: 0x557dea8678 - std::rt::lang_start::{{closure}}::h799cfbd68aba8b2c
Sep 09 02:32:42 raspberrypi librespot[644]: 33: 0x557e227bb0 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h45dcae2eefdb747f
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/core/src/ops/function.rs:280:13
Sep 09 02:32:42 raspberrypi librespot[644]: 34: 0x557e227bb0 - std::panicking::try::do_call::h34e1226c96866cf0
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:492:40
Sep 09 02:32:42 raspberrypi librespot[644]: 35: 0x557e227bb0 - std::panicking::try::h8d1dc95a49398e32
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:456:19
Sep 09 02:32:42 raspberrypi librespot[644]: 36: 0x557e227bb0 - std::panic::catch_unwind::hd66ee38629e2dc58
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panic.rs:137:14
Sep 09 02:32:42 raspberrypi librespot[644]: 37: 0x557e227bb0 - std::rt::lang_start_internal::{{closure}}::hb38034cfacc4173d
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/rt.rs:128:48
Sep 09 02:32:42 raspberrypi librespot[644]: 38: 0x557e227bb0 - std::panicking::try::do_call::h2811752b12903db4
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:492:40
Sep 09 02:32:42 raspberrypi librespot[644]: 39: 0x557e227bb0 - std::panicking::try::haa90604e26fdb3c6
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panicking.rs:456:19
Sep 09 02:32:42 raspberrypi librespot[644]: 40: 0x557e227bb0 - std::panic::catch_unwind::h1f317b68a309cc71
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/panic.rs:137:14
Sep 09 02:32:42 raspberrypi librespot[644]: 41: 0x557e227bb0 - std::rt::lang_start_internal::hfb3b3ed4bb8bd7fd
Sep 09 02:32:42 raspberrypi librespot[644]: at /rustc/4b91a6ea7258a947e59c6522cd5898e7c0a6a88f/library/std/src/rt.rs:128:20
Sep 09 02:32:42 raspberrypi librespot[644]: 42: 0x557dea0e28 - main
Sep 09 02:32:43 raspberrypi librespot[644]: 43: 0x7f936912fc - __libc_start_call_main
Sep 09 02:32:43 raspberrypi librespot[644]: at ./csu/../sysdeps/nptl/libc_start_call_main.h:58:16
Sep 09 02:32:43 raspberrypi librespot[644]: 44: 0x7f936913cc - __libc_start_main_impl
Sep 09 02:32:43 raspberrypi librespot[644]: at ./csu/../csu/libc-start.c:389:3
Sep 09 02:32:43 raspberrypi librespot[644]: 45: 0x557de1a64c - <unknown>That's a panic (un-handled error that leads to a hard and nasty crash in Rust speak) in libmdns caused by an index being out of range in a mdns packet. That's upstream of even librespot let alone Raspotify. Nothing can be done about that here or even at librespot. That would need to be fixed in libmdns (if it hasn't already?).
mDNS is a strange beast in that A LOT of hardware vendors don't implement it correctly in network devices. My old wifi router (now turn wireless AP, a TPLINK) for example would do similar things. Judging from the weird mDNS errors before the crash you may have the same problem? A shit implementation.
In any case this is beyond what can be done here.
This is an upstream issue. You should file an issue with librespot.
The fix in libmdns would be for them to check the length of the packet before they try to access an index that is potentially out of range, and if the index they want is > length to return an error that librespot can handle and exit cleanly so it can restart.
The reason that systemd does not restart on a panic is that by default rust programs just hang on a panic thus systemd thinks librespot is still running. I'm pretty sure I can make it so a panic makes librespot abort? At least then systemd can restart the service.
I'm hoping this commit will at least prevent librespot from hanging on a panic and allow systemd to restart the Raspotify service. I pushed an update to the repo, it should be live shortly, give it a try and see if that elevates the need to manually restart the service when you hit a libmdns panic.
I'm getting a ghostly 'Playback Restricted' under traspotify in the device selection list for spotify on my iPad.
It could be that spotify blocking raspotify.
Thanks for the quick response @JasonLG1979 . Making systemd restart the service at panic is indeed good enough; my initial plan was to set up a cron job checking some logs and deciding upon that whether to restart or not, but this is way better imo. Will update and let it run for a while.
I'm getting a ghostly 'Playback Restricted' under traspotify in the device selection list for spotify on my iPad.
It could be that spotify blocking raspotify.
That is not a Librespot/Raspotify specific issue:
It's also off topic. Don't hijack issues with unrelated bugs.
Thanks for the quick response @JasonLG1979 . Making systemd restart the service at panic is indeed good enough; my initial plan was to set up a cron job checking some logs and deciding upon that whether to restart or not, but this is way better imo. Will update and let it run for a while.
No problem. Hopefully it works as intended. To be clear though aborting on panic means we give up tracebacks so you should only see the warning log messages and maybe something from systemd about librespot aborting.
I'm getting a ghostly 'Playback Restricted' under traspotify in the device selection list for spotify on my iPad.
It could be that spotify blocking raspotify.That is not a Librespot/Raspotify specific issue:
It's also off topic. Don't hijack issues with unrelated bugs.
I didn’t believe I was hijkacking. I honestly thought it may have been a missed diagnostic. My deployment has been running for years, and kept up to date. Failed today at roughly the time this issue was reported. It’s not a big deal for me to report a new issue. Try to be friendly.
I’ve looked at the linked issue, and all I can see is noise about branded devices - which I don’t own. I only have raspotify. Which I did a full apt upgrade and a reboot of, before my comment was posted. I may have missed something.
Try to be friendly.
It's not about being friendly or not. You haven't done your due diligence. You provided no info at all about your issue and you are in fact trying to hijack an issue even if you realize it or not. It's non-productive to comment "It's not working." and provide nothing that can even connect your issue to this one.
No one here is a psychic technomancer to my knowledge. We can't see into your computer and read your logs.
@pjgoodall: @blubbafett provided an excellent bug report. They provided all of their package and system info, They clearly stated the issue and the expected desired behavior, and they provided logs. You did none of those things well or at all.
@pjgoodall: @blubbafett provided an excellent bug report. They provided all of their package and system info, They clearly stated the issue and the expected desired behavior, and they provided logs. You did none of those things well or at all.
😍
@pjgoodall: @blubbafett provided an excellent bug report. They provided all of their package and system info, They clearly stated the issue and the expected desired behavior, and they provided logs. You did none of those things well or at all.
heart_eyes
I'm not sure what that means but if you're not going to be productive you're going to catch a ban.
@JasonLG1979 I can confirm that the patch works for restarting raspotify when lbrespot crashes due to the mDNS issue. Seems like it crashed again last night, but up and running again directly after, so all good.
Sep 17 19:09:27 raspberrypi librespot[888]: thread 'main' panicked at 'range end index 9 out of range for slice of length 5', library/core/src/slice/index.rs:73:5
Sep 17 19:09:27 raspberrypi librespot[888]: stack backtrace:
Sep 17 19:09:27 raspberrypi librespot[888]: 0: 0x557deeaef4 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 1: 0x557df0c9e0 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 2: 0x557dee58d4 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 3: 0x557deec56c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 4: 0x557deec2c0 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 5: 0x557deecab8 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 6: 0x557deec9a0 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 7: 0x557deeb39c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 8: 0x557deec6ec - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 9: 0x557dbb6990 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 10: 0x557df0e300 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 11: 0x557df0603c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 12: 0x557df09d98 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 13: 0x557dbb6a4c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 14: 0x557dc7309c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 15: 0x557dc7ad08 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 16: 0x557dc74de8 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 17: 0x557dc6e688 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 18: 0x557dc700c8 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 19: 0x557dc7a908 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 20: 0x557dc778fc - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 21: 0x557dc14db4 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 22: 0x557dbe6dac - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 23: 0x557dc14998 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 24: 0x557dbe7c0c - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 25: 0x557dc05034 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 26: 0x557dc25704 - <unknown>
Sep 17 19:09:27 raspberrypi librespot[888]: 27: 0x557dc18730 - <unknown>
Sep 17 19:09:27 raspberrypi systemd[1]: raspotify.service: Main process exited, code=killed, status=6/ABRT
Sep 17 19:09:27 raspberrypi systemd[1]: raspotify.service: Failed with result 'signal'.
Sep 17 19:09:27 raspberrypi systemd[1]: raspotify.service: Consumed 29min 6.773s CPU time.
Sep 17 19:09:38 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 1.
Sep 17 19:09:38 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 17 19:09:38 raspberrypi systemd[1]: raspotify.service: Consumed 29min 6.773s CPU time.
Sep 17 19:09:38 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 17 19:14:09 raspberrypi librespot[1300]: [2022-09-17T17:14:09Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Sep 17 19:14:09 raspberrypi librespot[1300]: [2022-09-17T17:14:09Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Sep 17 19:14:09 raspberrypi librespot[1300]: [2022-09-17T17:14:09Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Sep 17 19:14:09 raspberrypi librespot[1300]: [2022-09-17T17:14:09Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:443
Sep 17 19:14:10 raspberrypi librespot[1300]: [2022-09-17T17:14:10Z ERROR librespot] Connection failed: Authentication failed: bytes remaining on stream
Sep 17 19:14:10 raspberrypi systemd[1]: raspotify.service: Main process exited, code=exited, status=1/FAILURE
Sep 17 19:14:10 raspberrypi systemd[1]: raspotify.service: Failed with result 'exit-code'.
Sep 17 19:14:20 raspberrypi systemd[1]: raspotify.service: Scheduled restart job, restart counter is at 2.
Sep 17 19:14:20 raspberrypi systemd[1]: Stopped Raspotify (Spotify Connect Client).
Sep 17 19:14:20 raspberrypi systemd[1]: Started Raspotify (Spotify Connect Client).
Sep 17 19:14:25 raspberrypi librespot[1311]: [2022-09-17T17:14:25Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Sep 17 19:14:25 raspberrypi librespot[1311]: [2022-09-17T17:14:25Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Sep 17 19:14:25 raspberrypi librespot[1311]: [2022-09-17T17:14:25Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Sep 17 19:14:25 raspberrypi librespot[1311]: [2022-09-17T17:14:25Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Sep 18 05:38:20 raspberrypi librespot[1311]: [2022-09-18T03:38:20Z WARN libmdns::fsm] couldn't parse packet from <removed from log>.168.30.1:5353: packet has non-zero reserved bits
Sep 18 09:53:43 raspberrypi librespot[1311]: [2022-09-18T07:53:43Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:4070
Sep 18 09:53:43 raspberrypi librespot[1311]: [2022-09-18T07:53:43Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:443
Sep 18 09:53:43 raspberrypi librespot[1311]: [2022-09-18T07:53:43Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gew4.spotify.com:80
Sep 18 09:53:43 raspberrypi librespot[1311]: [2022-09-18T07:53:43Z WARN librespot_core::apresolve] Ignoring blacklisted access point ap-gue1.spotify.com:4070
Sep 18 12:47:00 raspberrypi librespot[1311]: [2022-09-18T10:47:00Z WARN libmdns::fsm] couldn't parse packet from <removed from log>.168.30.1:5353: packet has non-zero reserved bits
Sep 18 13:10:42 raspberrypi librespot[1311]: [2022-09-18T11:10:42Z WARN libmdns::fsm] couldn't parse packet from <removed from log>.168.30.1:5353: packet has non-zero reserved bits
Sep 18 17:41:25 raspberrypi librespot[1311]: [2022-09-18T15:41:25Z WARN libmdns::fsm] couldn't parse packet from <removed from log>.168.30.1:5353: packet is smaller than header sizeSo I guess that this issue can be closed now. Thanks again for resolving it so quickly.
Hopefully this maybe won't be an issue at all once I switch over to OpnSense/pfSense at some point.
Well it looks like we do get tracebacks from dependencies so I might not strip the binary after all. Thanks for your help and I'm glad it worked out for you.
Hopefully this maybe won't be an issue at all once I switch over to OpnSense/pfSense at some point.
If you use it as a router It'll work better I'd imagine. I ended up getting a cheap little Ubiquity EdgeRouter X specifically because it runs Debian, and I haven't had an issue since.
I released 0.42.6 which basically just adds those sweet, sweet traceback back in (it will still abort). I love me some tracebacks for debugging.
@pjgoodall: @blubbafett provided an excellent bug report. They provided all of their package and system info, They clearly stated the issue and the expected desired behavior, and they provided logs. You did none of those things well or at all.
heart_eyes
I'm not sure what that means but if you're not going to be productive you're going to catch a ban.
This is how you respond without being abusive. No accusations of hijacking here:
conda/conda#7202 (comment)
@pjgoodall: @blubbafett provided an excellent bug report. They provided all of their package and system info, They clearly stated the issue and the expected desired behavior, and they provided logs. You did none of those things well or at all.
heart_eyes
I'm not sure what that means but if you're not going to be productive you're going to catch a ban.
This is how you respond without being abusive. No accusations of hijacking here: conda/conda#7202 (comment)
Stating facts is not abusive. It seems that you just are incapable of understanding how bug reports work? Your profile says you have many years in software development. You should know better
I would have been nicer too a noob. You are not a noob.
That is fine you are not welcome here.
@blubbafett if you have any further issues please file another bug report even if it's a duplicate or closely related to this issue. I'm going to lock this issue for obvious reasons.