panic in setup.rs: DnsSdError ( Os 19 "No such device" )

[grandchild]

Hi there,

thanks for the really lovely software, it's purring along since over a year now, and brought us much easy joy!

Description This unwrap() here

https://github.com/Spotifyd/spotifyd/blob/0a15027f1aa5cf9f306a2ffdbc433e6f32911ccf/src/setup.rs#L105

panics sometimes with

DnsSdError(Os { code: 19, kind: Uncategorized, message: "No such device" })

From the journal it seems this first occurred on 2023-05-07, with spotifyd upgraded to 0.3.5 a few days earlier:

[2023-05-06T15:39:27+0200] [ALPM] upgraded spotifyd (0.3.4-1 -> 0.3.5-1)

In all cases, after some time (~2min +/-2min), during which the service restarts a few times, it works.

As you can see from the logs below it corresponds to reboots most of the time (but not every time!), and the error talks of DNS -- so I suspect some network-down situation being the cause. Although you already do After=network-online.target in the service file (which I'm using). 🤔

I may look into this myself at some point, but I can't right now. But I thought I'd report anyway, because it looks like a simple unwrap_or_else() or other error handling or controlled backoff-wait loop might already help?

To Reproduce I haven't tried actively recreating the issue, yet.

Expected behavior Not crash.

Logs

Click to show logs

A sample errored run:

Oct 08 20:41:52 spotifyd[567]: Loading config from "/home/<redacted>/.config/spotifyd/spotifyd.conf"
Oct 08 20:41:52 spotifyd[567]: No username specified. Checking username_cmd
Oct 08 20:41:52 spotifyd[567]: No username_cmd specified
Oct 08 20:41:52 spotifyd[567]: No password specified. Checking password_cmd
Oct 08 20:41:52 spotifyd[567]: No password_cmd specified
Oct 08 20:41:52 spotifyd[567]: No proxy specified
Oct 08 20:41:52 spotifyd[567]: Using software volume controller.
Oct 08 20:41:52 spotifyd[567]: no usable credentials found, enabling discovery
Oct 08 20:41:52 spotifyd[567]: The application panicked (crashed).
Oct 08 20:41:52 spotifyd[567]: Message:  called `Result::unwrap()` on an `Err` value: DnsSdError(Os { code: 19, kind: Uncategorized, message: "No such device" })
Oct 08 20:41:52 spotifyd[567]: Location: src/setup.rs:105

Historical summary of events (grepped only the error lines)

May 07 03:20:09 spotifyd[445]: ... DnsSdError ...
May 07 03:25:41 spotifyd[442]: ... DnsSdError ...

Jun 27 22:48:18 spotifyd[441]: ... DnsSdError ...
Jun 27 22:48:30 spotifyd[498]: ... DnsSdError ...
Jun 27 22:48:42 spotifyd[503]: ... DnsSdError ...
Jun 27 22:48:54 spotifyd[510]: ... DnsSdError ...
Jun 27 22:49:07 spotifyd[515]: ... DnsSdError ...
Jun 27 22:49:19 spotifyd[520]: ... DnsSdError ...
Jun 27 22:49:31 spotifyd[525]: ... DnsSdError ...
Jun 27 22:49:43 spotifyd[530]: ... DnsSdError ...

Jul 22 21:39:03 spotifyd[447]: ... DnsSdError ...
Jul 22 21:39:16 spotifyd[488]: ... DnsSdError ...
Jul 22 21:39:28 spotifyd[493]: ... DnsSdError ...
Jul 22 21:39:40 spotifyd[500]: ... DnsSdError ...
Jul 22 21:39:52 spotifyd[505]: ... DnsSdError ...
Jul 22 21:40:05 spotifyd[510]: ... DnsSdError ...
Jul 22 21:40:17 spotifyd[515]: ... DnsSdError ...
Jul 22 21:40:29 spotifyd[520]: ... DnsSdError ...

Aug 03 13:32:15 spotifyd[490]: ... DnsSdError ...

Aug 26 12:35:05 spotifyd[499]: ... DnsSdError ...

Oct 04 21:05:28 spotifyd[496]: ... DnsSdError ...
Oct 04 21:05:41 spotifyd[546]: ... DnsSdError ...
Oct 04 21:05:53 spotifyd[552]: ... DnsSdError ...
Oct 04 21:06:05 spotifyd[561]: ... DnsSdError ...
Oct 04 21:06:18 spotifyd[567]: ... DnsSdError ...
Oct 04 21:06:30 spotifyd[573]: ... DnsSdError ...
Oct 04 21:06:42 spotifyd[579]: ... DnsSdError ...
Oct 04 21:06:54 spotifyd[585]: ... DnsSdError ...

Oct 04 21:16:03 spotifyd[495]: ... DnsSdError ...
Oct 04 21:16:15 spotifyd[559]: ... DnsSdError ...
Oct 04 21:16:27 spotifyd[565]: ... DnsSdError ...
Oct 04 21:16:40 spotifyd[582]: ... DnsSdError ...
Oct 04 21:16:52 spotifyd[588]: ... DnsSdError ...
Oct 04 21:17:04 spotifyd[594]: ... DnsSdError ...
Oct 04 21:17:16 spotifyd[600]: ... DnsSdError ...
Oct 04 21:17:29 spotifyd[606]: ... DnsSdError ...

Oct 08 20:02:49 spotifyd[547]: ... DnsSdError ...
Oct 08 20:03:01 spotifyd[553]: ... DnsSdError ...
Oct 08 20:03:14 spotifyd[562]: ... DnsSdError ...
Oct 08 20:03:26 spotifyd[568]: ... DnsSdError ...
Oct 08 20:03:38 spotifyd[574]: ... DnsSdError ...
Oct 08 20:03:50 spotifyd[580]: ... DnsSdError ...
Oct 08 20:04:03 spotifyd[586]: ... DnsSdError ...

Oct 08 20:09:12 spotifyd[491]: ... DnsSdError ...
Oct 08 20:09:24 spotifyd[544]: ... DnsSdError ...
Oct 08 20:09:36 spotifyd[550]: ... DnsSdError ...
Oct 08 20:09:49 spotifyd[559]: ... DnsSdError ...
Oct 08 20:10:01 spotifyd[565]: ... DnsSdError ...
Oct 08 20:10:13 spotifyd[571]: ... DnsSdError ...
Oct 08 20:10:25 spotifyd[577]: ... DnsSdError ...
Oct 08 20:10:38 spotifyd[583]: ... DnsSdError ...

Oct 08 20:41:03 spotifyd[492]: ... DnsSdError ...
Oct 08 20:41:15 spotifyd[546]: ... DnsSdError ...
Oct 08 20:41:27 spotifyd[552]: ... DnsSdError ...
Oct 08 20:41:40 spotifyd[561]: ... DnsSdError ...
Oct 08 20:41:52 spotifyd[567]: ... DnsSdError ...
Oct 08 20:42:04 spotifyd[573]: ... DnsSdError ...
Oct 08 20:42:16 spotifyd[579]: ... DnsSdError ...
Oct 08 20:42:29 spotifyd[585]: ... DnsSdError ...

This corresponds nicely to reboots recently, but earlier, not so much:

$ journalctl --list-boots
IDX BOOT ID                          FIRST ENTRY                  LAST ENTRY                  
-12 b16557e9a4d04666815c95806cce80a1 Tue 2023-04-11 19:48:50 CEST Wed 2023-05-31 15:45:33 CEST
-11 4882ff5221ab4c10ab9e4fbe964c33b2 Tue 2023-05-09 04:24:13 CEST Sun 2023-06-25 21:50:26 CEST
-10 a7a7fcdc26774011882b75729fae7a09 Tue 2023-06-20 14:42:21 CEST Tue 2023-06-27 22:41:54 CEST
 -9 bf7284be3a5e45d2b7e7bfd8a6d64cbd Tue 2023-06-20 14:42:21 CEST Sat 2023-07-22 02:59:02 CEST
 -8 32b4e873f7664eb89865daf1f0c9b5cb Tue 2023-06-20 14:42:21 CEST Thu 2023-08-03 13:32:15 CEST
 -7 f77390d6a8c34df6afe045dca6ad410c Thu 2023-08-03 13:32:15 CEST Sat 2023-08-26 12:35:03 CEST
 -6 bb8dcd983cc84da89b82a3896160c7c2 Sat 2023-08-26 12:35:05 CEST Sat 2023-09-30 20:38:18 CEST
 -5 3cd6083c515949ab9ef08a28de72ffd7 Sat 2023-09-30 20:38:18 CEST Wed 2023-10-04 20:54:54 CEST
 -4 1dd9b1bea7a74340a8db28db5d2a9987 Wed 2023-10-04 21:05:26 CEST Wed 2023-10-04 21:07:59 CEST
 -3 99e72353850c4aa1b5199e0772a1c8ab Wed 2023-10-04 21:16:00 CEST Sun 2023-10-08 19:58:55 CEST
 -2 a2ba9dbb56ad4d1284e6bcee7a7d06e3 Sun 2023-10-08 20:02:34 CEST Sun 2023-10-08 20:05:25 CEST
 -1 9148697e9dd3456f82dc711e413b978d Sun 2023-10-08 20:09:09 CEST Sun 2023-10-08 20:38:34 CEST
  0 e973215ed3cc40b2aafacf249e38e0d6 Sun 2023-10-08 20:41:00 CEST Wed 2023-10-11 08:44:43 CEST

Versions (please complete the following information):

• OS: Archlinux ARM64 (on a raspi4)
• Spotifyd: pkgver 0.3.5-1
• cargo: n/a, since built by distro

[eladyn]

Thank you for the elaborate report. The fix you propose (implementing a retry-strategy) sounds like a good idea, however I'd still be interested, where exactly starting discovery fails. Would you be able to get such a log with --verbose being enabled?

[grandchild]

logs with --verbose & RUST_BACKTRACE=1

I shortened the line with repetitive binary output, it's <E2><94><81> repeated multiple times.

Oct 16 10:54:39 spotifyd[489]: Loading config from "/home/me/.config/spotifyd/spotifyd.conf"
Oct 16 10:54:39 spotifyd[489]: CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: None, username_cmd: None, password: None, password_cmd: None, use_keyring: false, use_mpris: None, dbus_type: None, on_song_change_hook
Oct 16 10:54:39 spotifyd[489]: : None, cache_path: None, no-audio-cache: false, backend: Some(PulseAudio), volume_controller: None, device: None, control: None, mixer: None, device_name: Some("my_hostname"), bitrate: Some(Bitrate320), audio_format: None, initial_volume: Some("40"), volume_no
Oct 16 10:54:39 spotifyd[489]: rmalisation: true, normalisation_pregain: Some(-7.0), zeroconf_port: None, proxy: None, device_type: Some(Speaker), autoplay: false, max_cache_size: None } }
Oct 16 10:54:39 spotifyd[489]: Found user shell: Some("/bin/bash")
Oct 16 10:54:39 spotifyd[489]: No username specified. Checking username_cmd
Oct 16 10:54:39 spotifyd[489]: No username_cmd specified
Oct 16 10:54:39 spotifyd[489]: No password specified. Checking password_cmd
Oct 16 10:54:39 spotifyd[489]: No password_cmd specified
Oct 16 10:54:39 spotifyd[489]: No proxy specified
Oct 16 10:54:39 spotifyd[489]: registering event source with poller: token=Token(2147483649), interests=READABLE
Oct 16 10:54:39 spotifyd[489]: Using software volume controller.
Oct 16 10:54:39 spotifyd[489]: no usable credentials found, enabling discovery
Oct 16 10:54:39 spotifyd[489]: Using device id '9424ac79de34c97c74261622b533d185ca13968a'
Oct 16 10:54:38 systemd[478]: Started A spotify playing daemon.
Oct 16 10:54:39 spotifyd[489]: registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
Oct 16 10:54:39 spotifyd[489]: Zeroconf server listening on 0.0.0.0:43147
Oct 16 10:54:39 spotifyd[489]: Shutting down discovery server
Oct 16 10:54:39 spotifyd[489]: deregistering event source from poller
Oct 16 10:54:39 spotifyd[489]: The application panicked (crashed).
Oct 16 10:54:39 spotifyd[489]: Message:  called `Result::unwrap()` on an `Err` value: DnsSdError(Os { code: 19, kind: Uncategorized, message: "No such device" })
Oct 16 10:54:39 spotifyd[489]: Location: src/setup.rs:105
Oct 16 10:54:39 spotifyd[489]:   <E2><94><81>[32x omitted]<E2><94><81> BACKTRACE <E2><94><81>[33x omitted]<E2><94><81>
Oct 16 10:54:39 spotifyd[489]:    1: main<unknown>
Oct 16 10:54:39 spotifyd[489]:       at <unknown source file>:<unknown line>
Oct 16 10:54:39 spotifyd[489]:    2: __libc_start_main<unknown>
Oct 16 10:54:39 spotifyd[489]:       at <unknown source file>:<unknown line>
Oct 16 10:54:39 spotifyd[489]: Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
Oct 16 10:54:39 spotifyd[489]: Run with RUST_BACKTRACE=full to include source snippets.
Oct 16 10:54:39 systemd[478]: spotifyd.service: Main process exited, code=exited, status=101/n/a
Oct 16 10:54:39 systemd[478]: spotifyd.service: Failed with result 'exit-code'.



Oct 16 10:54:51 systemd[478]: spotifyd.service: Scheduled restart job, restart counter is at 1.
Oct 16 10:54:51 systemd[478]: Started A spotify playing daemon.
Oct 16 10:54:51 spotifyd[589]: Loading config from "/home/me/.config/spotifyd/spotifyd.conf"
Oct 16 10:54:51 spotifyd[589]: CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: None, username_cmd: None, password: None, password_cmd: None, use_keyring: false, use_mpris: None, dbus_type: None, on_song_change_hook: None, cache_path: None, no-audio-cache: false, backend: Some(PulseAudio), volume_controller: None, device: None, control: None, mixer: None, device_name: Some("my_hostname"), bitrate: Some(Bitrate320), audio_format: None, initial_volume: Some("40"), volume_normalisation: true, normalisation_pregain: Some(-7.0), zeroconf_port: None, proxy: None, device_type: Some(Speaker), autoplay: false, max_cache_size: None } }
Oct 16 10:54:51 spotifyd[589]: Found user shell: Some("/bin/bash")
Oct 16 10:54:51 spotifyd[589]: No username specified. Checking username_cmd
Oct 16 10:54:51 spotifyd[589]: No username_cmd specified
Oct 16 10:54:51 spotifyd[589]: No password specified. Checking password_cmd
Oct 16 10:54:51 spotifyd[589]: No password_cmd specified
Oct 16 10:54:51 spotifyd[589]: No proxy specified
Oct 16 10:54:51 spotifyd[589]: registering event source with poller: token=Token(2147483649), interests=READABLE
Oct 16 10:54:51 spotifyd[589]: Using software volume controller.
Oct 16 10:54:51 spotifyd[589]: no usable credentials found, enabling discovery
Oct 16 10:54:51 spotifyd[589]: Using device id '9424ac79de34c97c74261622b533d185ca13968a'
Oct 16 10:54:51 spotifyd[589]: registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
Oct 16 10:54:51 spotifyd[589]: Zeroconf server listening on 0.0.0.0:44849
Oct 16 10:54:51 spotifyd[589]: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
Oct 16 10:54:51 spotifyd[589]: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
Oct 16 10:54:51 spotifyd[589]: found interface Interface { name: "wlan0", addr: V4(Ifv4Addr { ip: 192.168.2.174, netmask: 255.255.255.0, broadcast: Some(192.168.2.255) }) }
Oct 16 10:54:51 spotifyd[589]: sending packet to 224.0.0.251:5353
Oct 16 10:54:51 spotifyd[589]: found interface Interface { name: "wlan0", addr: V4(Ifv4Addr { ip: 192.168.2.174, netmask: 255.255.255.0, broadcast: Some(192.168.2.255) }) }
Oct 16 10:54:51 spotifyd[589]: sending packet to [ff02::fb]:5353

[eladyn]

Thank you for the feedback. Judging by the logs it seems indeed like that is the libmdns code that somehow fails to bind (as the http server part seems to work fine).

If you are motivated and have the time, you could try to compile the libmdns example and run that on startup. If that fails (which it should, if my assumptions are correct), you could open a bug report over there.

In any case, I think the fix that I wrote should be fine for now. If you want, you can have a look at it and try it out.

[grandchild]

After creating /home/me/.config/systemd/user/rust-mdns-debug-example.service with

[Unit]
Description=Debug MDNS rust lib
Wants=sound.target
After=sound.target
Wants=network-online.target
After=network-online.target

[Service]
Environment=RUST_BACKTRACE=full
ExecStart=/home/me/dev/src/libmdns/target/debug/examples/register
Restart=always
RestartSec=12

[Install]
WantedBy=default.target

which mirrors the service file for spotifyd, and enabling that on boot, I do indeed see:

-- Boot 09cfc76929644b2eb8c6c6ea1039dd94 --
Oct 17 10:01:53 my_hostname register[502]: thread 'main' panicked at examples/register.rs:6:47:
Oct 17 10:01:53 my_hostname register[502]: called `Result::unwrap()` on an `Err` value: Os { code: 19, kind: Uncategorized, message: "No such device" }
Oct 17 10:01:53 my_hostname register[502]: stack backtrace:
Oct 17 10:01:53 my_hostname register[502]:    0:   0x53092c - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h3e8ebc5fb7df0e6b
Oct 17 10:01:53 my_hostname register[502]:    1:   0x5527a0 - core::fmt::write::h8cad70b1293ee148
Oct 17 10:01:53 my_hostname register[502]:    2:   0x52df3c - std::io::Write::write_fmt::hc1dc85370fdc562b
Oct 17 10:01:53 my_hostname register[502]:    3:   0x53073c - std::sys_common::backtrace::print::hedd06b77333ae10f
Oct 17 10:01:53 my_hostname register[502]:    4:   0x532030 - std::panicking::default_hook::{{closure}}::h0b156d4f87f4f89b
Oct 17 10:01:53 my_hostname register[502]:    5:   0x531d00 - std::panicking::default_hook::h5149f410ff710918
Oct 17 10:01:53 my_hostname register[502]:    6:   0x532724 - std::panicking::rust_panic_with_hook::h6865010e21e71ae2
Oct 17 10:01:53 my_hostname register[502]:    7:   0x532448 - std::panicking::begin_panic_handler::{{closure}}::haf87210c9ad65383
Oct 17 10:01:53 my_hostname register[502]:    8:   0x530ee8 - std::sys_common::backtrace::__rust_end_short_backtrace::h981eb205ad650d01
Oct 17 10:01:53 my_hostname register[502]:    9:   0x5321fc - rust_begin_unwind
Oct 17 10:01:53 my_hostname register[502]:   10:   0x438578 - core::panicking::panic_fmt::hfcac5508ecfe66fe
Oct 17 10:01:53 my_hostname register[502]:   11:   0x4389a8 - core::result::unwrap_failed::ha9af6bbbb66dab98
Oct 17 10:01:53 my_hostname register[502]:   12:   0x438e54 - core::result::Result<T,E>::unwrap::he38994bbc9dfd77d
Oct 17 10:01:53 my_hostname register[502]:                        at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library/core/src/result.rs:1077:23
Oct 17 10:01:53 my_hostname register[502]:   13:   0x4391a0 - register::main::h6d2af902d7b66d16
Oct 17 10:01:53 my_hostname register[502]:                        at /home/me/dev/src/libmdns/examples/register.rs:6:21
Oct 17 10:01:53 my_hostname register[502]:   14:   0x439348 - core::ops::function::FnOnce::call_once::h6570f9bdc1c7ff20
Oct 17 10:01:53 my_hostname register[502]:                        at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library/core/src/ops/function.rs:250:5
Oct 17 10:01:53 my_hostname register[502]:   15:   0x4390d0 - std::sys_common::backtrace::__rust_begin_short_backtrace::hdcec34e326b4e202
Oct 17 10:01:53 my_hostname register[502]:                        at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library/std/src/sys_common/backtrace.rs:154:18
Oct 17 10:01:53 my_hostname register[502]:   16:   0x438f04 - std::rt::lang_start::{{closure}}::h84510bde85a29ccb
Oct 17 10:01:53 my_hostname register[502]:                        at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library/std/src/rt.rs:166:18
Oct 17 10:01:53 my_hostname register[502]:   17:   0x52a180 - std::rt::lang_start_internal::h0bc5a6b1913e9fc7
Oct 17 10:01:53 my_hostname register[502]:   18:   0x438ed4 - std::rt::lang_start::h0d26d60cbe439ee2
Oct 17 10:01:53 my_hostname register[502]:                        at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library/std/src/rt.rs:165:17
Oct 17 10:01:53 my_hostname register[502]:   19:   0x439308 - main
Oct 17 10:01:53 my_hostname register[502]:   20: 0xb6dad9dc - <unknown>
Oct 17 10:01:53 my_hostname register[502]:   21: 0xb6dadaf0 - __libc_start_main
Oct 17 10:01:51 my_hostname systemd[490]: Started Debug MDNS rust lib.
Oct 17 10:01:53 my_hostname systemd[490]: rust-mdns-debug-example.service: Main process exited, code=exited, status=101/n/a
Oct 17 10:01:53 my_hostname systemd[490]: rust-mdns-debug-example.service: Failed with result 'exit-code'.
Oct 17 10:02:05 my_hostname systemd[490]: rust-mdns-debug-example.service: Scheduled restart job, restart counter is at 1.
Oct 17 10:02:05 my_hostname systemd[490]: Started Debug MDNS rust lib.
Oct 17 10:02:07 my_hostname register[612]: [2023-10-17T08:02:07Z DEBUG libmdns::fsm] received question: IN my_hostname.local
Oct 17 10:02:07 my_hostname register[612]: [2023-10-17T08:02:07Z DEBUG libmdns::fsm] received question: IN my_hostname.local
Oct 17 10:02:07 my_hostname register[612]: [2023-10-17T08:02:07Z DEBUG libmdns::fsm] received question: IN my_hostname.local
Oct 17 10:02:07 my_hostname register[612]: [2023-10-17T08:02:07Z DEBUG libmdns::fsm] received question: IN my_hostname.local
Oct 17 10:02:07 my_hostname register[612]: [2023-10-17T08:02:07Z DEBUG libmdns::fsm] received question: IN my_hostname.local

[grandchild]

I'll make a bug report over there these days.

Thanks for the quick solve! Carry on :)

[Drexel2k]

I saw you already coded a patch and wait for feedback on a libmdns issue, but no one opened an issues over there. :) I can do it the next days...

[eladyn]

@Drexel2k that would be awesome!

[Drexel2k]

Finally I did, sorry for the delay.