Repository: Spotifyd/spotifyd (language: rust)

Issue:
panic in setup.rs: DnsSdError ( Os 19 "No such device" )
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

```rust
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**
<details><summary>Click to show logs</summary>

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
```

</details>

**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


Discussion / hints:
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?

Fix patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 1e521ed0..a8081550 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -6,10 +6,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Added
+- retry enabling discovery several times before exiting ([#1228])
+
 ### Changed
 - Credential caching has been re-enabled. ([#1214])
 
 [#1214]: https://github.com/Spotifyd/spotifyd/pull/1214
+[#1228]: https://github.com/Spotifyd/spotifyd/pull/1228
 
 ## [0.3.5]
 
diff --git a/src/setup.rs b/src/setup.rs
index e2538cf8..07a713c3 100644
--- a/src/setup.rs
+++ b/src/setup.rs
@@ -15,7 +15,7 @@ use librespot_playback::{
 };
 #[allow(unused_imports)] // cfg
 use log::{debug, error, info, warn};
-use std::str::FromStr;
+use std::{str::FromStr, thread, time::Duration};
 
 pub(crate) fn initial_state(config: config::SpotifydConfig) -> main_loop::MainLoop {
     let mixer = {
@@ -96,13 +96,30 @@ pub(crate) fn initial_state(config: config::SpotifydConfig) -> main_loop::MainLo
         } else {
             info!("no usable credentials found, enabling discovery");
             debug!("Using device id '{}'", session_config.device_id);
-            let discovery_stream =
-                librespot_discovery::Discovery::builder(session_config.device_id.clone())
+            const RETRY_MAX: u8 = 4;
+            let mut retry_counter = 0;
+            let mut backoff = Duration::from_secs(5);
+            let discovery_stream = loop {
+                match librespot_discovery::Discovery::builder(session_config.device_id.clone())
                     .name(config.device_name.clone())
                     .device_type(device_type)
                     .port(zeroconf_port)
                     .launch()
-                    .unwrap();
+                {
+                    Ok(discovery_stream) => break discovery_stream,
+                    Err(err) => {
+                        error!("failed to enable discovery: {err}");
+                        if retry_counter >= RETRY_MAX {
+                            panic!("failed to enable discovery (and no credentials provided)");
+                        }
+                        info!("retrying discovery in {} seconds", backoff.as_secs());
+                        thread::sleep(backoff);
+                        retry_counter += 1;
+                        backoff *= 2;
+                        info!("trying to enable discovery (retry {retry_counter}/{RETRY_MAX})");
+                    }
+                }
+            };
             discovery_stream.into()
         };
 


Test patch: