-- Logs begin at Fri 2025-05-09 03:56:26 CEST, end at Fri 2025-05-09 05:45:43 CEST. -- May 09 05:44:02 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:02 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:02 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:02 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2741. May 09 05:44:02 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:02 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:02 primo go-librespot[26691]: Librespot-go daemon starting... May 09 05:44:02 primo go-librespot[26691]: time="2025-05-09T05:44:02+02:00" level=info msg="generated new device id: 590926ac8673b1e6dc80fb4c9ab99543e62c62c8" May 09 05:44:02 primo go-librespot[26691]: time="2025-05-09T05:44:02+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:02 primo go-librespot[26691]: time="2025-05-09T05:44:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:02 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:02 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:04 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:04 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:04 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:05 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:05 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:05 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:05 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2742. May 09 05:44:05 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:05 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:05 primo go-librespot[26703]: Librespot-go daemon starting... May 09 05:44:05 primo go-librespot[26703]: time="2025-05-09T05:44:05+02:00" level=info msg="generated new device id: fe7c1f9a6cd3be5208ad8bc399a1e07df1effb52" May 09 05:44:05 primo go-librespot[26703]: time="2025-05-09T05:44:05+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:05 primo go-librespot[26703]: time="2025-05-09T05:44:05+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:05 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:05 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:08 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:08 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:09 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:09 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:09 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2743. May 09 05:44:09 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:09 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:09 primo go-librespot[26734]: Librespot-go daemon starting... May 09 05:44:09 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:09 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:09 primo go-librespot[26734]: time="2025-05-09T05:44:09+02:00" level=info msg="generated new device id: 1abb11d1edd7ff7d558090d84889a788fbf8323e" May 09 05:44:09 primo go-librespot[26734]: time="2025-05-09T05:44:09+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:09 primo go-librespot[26734]: time="2025-05-09T05:44:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:09 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:09 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:11 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:11 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:12 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:12 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2744. May 09 05:44:12 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:12 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:12 primo go-librespot[26783]: Librespot-go daemon starting... May 09 05:44:12 primo go-librespot[26783]: time="2025-05-09T05:44:12+02:00" level=info msg="generated new device id: cfaef42b903b634f13a398d5cf84ba9c6bd36d39" May 09 05:44:12 primo go-librespot[26783]: time="2025-05-09T05:44:12+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:12 primo go-librespot[26783]: time="2025-05-09T05:44:12+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:12 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:12 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:14 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:14 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:14 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:14 primo ntpd[3074]: error resolving pool 2.debian.pool.ntp.org: System error (-11) May 09 05:44:14 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:14 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:15 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:15 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2745. May 09 05:44:15 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:15 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:15 primo go-librespot[26795]: Librespot-go daemon starting... May 09 05:44:15 primo go-librespot[26795]: time="2025-05-09T05:44:15+02:00" level=info msg="generated new device id: f75c26081a83cc8661c9d9d15ea24e2a78a6cf26" May 09 05:44:15 primo go-librespot[26795]: time="2025-05-09T05:44:15+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:15 primo go-librespot[26795]: time="2025-05-09T05:44:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:15 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:15 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:17 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:17 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:18 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:18 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2746. May 09 05:44:18 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:18 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:18 primo go-librespot[26822]: Librespot-go daemon starting... May 09 05:44:18 primo go-librespot[26822]: time="2025-05-09T05:44:18+02:00" level=info msg="generated new device id: f03afa3a9a0a138ee26ba373bd663a24abf4b080" May 09 05:44:18 primo go-librespot[26822]: time="2025-05-09T05:44:18+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:18 primo go-librespot[26822]: time="2025-05-09T05:44:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:18 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:18 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:19 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:19 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:19 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:20 primo ntpd[3074]: error resolving pool 1.debian.pool.ntp.org: System error (-11) May 09 05:44:20 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:20 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:22 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:22 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2747. May 09 05:44:22 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:22 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:22 primo go-librespot[26834]: Librespot-go daemon starting... May 09 05:44:22 primo go-librespot[26834]: time="2025-05-09T05:44:22+02:00" level=info msg="generated new device id: f4851e964b4b5106e895ff765b834e3ba594b5fc" May 09 05:44:22 primo go-librespot[26834]: time="2025-05-09T05:44:22+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:22 primo go-librespot[26834]: time="2025-05-09T05:44:22+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:22 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:22 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:23 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:23 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:24 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:24 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:24 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:25 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:25 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2748. May 09 05:44:25 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:25 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:25 primo go-librespot[26846]: Librespot-go daemon starting... May 09 05:44:25 primo go-librespot[26846]: time="2025-05-09T05:44:25+02:00" level=info msg="generated new device id: bd9142242310fe50e5ea66fb7c1748d6740ba4f6" May 09 05:44:25 primo go-librespot[26846]: time="2025-05-09T05:44:25+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:25 primo go-librespot[26846]: time="2025-05-09T05:44:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:25 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:25 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:26 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:26 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:28 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:28 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2749. May 09 05:44:28 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:28 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:28 primo go-librespot[26856]: Librespot-go daemon starting... May 09 05:44:28 primo go-librespot[26856]: time="2025-05-09T05:44:28+02:00" level=info msg="generated new device id: 0c2ee2c05276439f726e8f6e1aaac4b9604357ab" May 09 05:44:28 primo go-librespot[26856]: time="2025-05-09T05:44:28+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:28 primo go-librespot[26856]: time="2025-05-09T05:44:28+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:28 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:28 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:29 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:29 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:29 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:29 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:29 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:31 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:31 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2750. May 09 05:44:31 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:31 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:31 primo go-librespot[26885]: Librespot-go daemon starting... May 09 05:44:31 primo go-librespot[26885]: time="2025-05-09T05:44:31+02:00" level=info msg="generated new device id: 0ea78da9d30df071ec0f85ff49a34ff44c8d71b2" May 09 05:44:31 primo go-librespot[26885]: time="2025-05-09T05:44:31+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:31 primo go-librespot[26885]: time="2025-05-09T05:44:31+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:31 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:31 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:32 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:32 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:34 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:34 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:34 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:35 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:35 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2751. May 09 05:44:35 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:35 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:35 primo go-librespot[26897]: Librespot-go daemon starting... May 09 05:44:35 primo go-librespot[26897]: time="2025-05-09T05:44:35+02:00" level=info msg="generated new device id: 94d8cb688cc6afc90ac9c0d4230757861e9ee315" May 09 05:44:35 primo go-librespot[26897]: time="2025-05-09T05:44:35+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:35 primo go-librespot[26897]: time="2025-05-09T05:44:35+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:35 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:35 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:35 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:35 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:38 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:38 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2752. May 09 05:44:38 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:38 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:38 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:38 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:38 primo go-librespot[26907]: Librespot-go daemon starting... May 09 05:44:38 primo go-librespot[26907]: time="2025-05-09T05:44:38+02:00" level=info msg="generated new device id: 48e292e2af8c3b71e2371d415c406252b54e138b" May 09 05:44:38 primo go-librespot[26907]: time="2025-05-09T05:44:38+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:38 primo go-librespot[26907]: time="2025-05-09T05:44:38+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:38 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:38 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:39 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:39 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:39 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:40 primo ntpd[3074]: error resolving pool 0.debian.pool.ntp.org: System error (-11) May 09 05:44:41 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:41 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:41 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:41 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2753. May 09 05:44:41 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:41 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:41 primo go-librespot[26936]: Librespot-go daemon starting... May 09 05:44:41 primo go-librespot[26936]: time="2025-05-09T05:44:41+02:00" level=info msg="generated new device id: f6c26bad007702089c290e21d0d9c6b43601af24" May 09 05:44:41 primo go-librespot[26936]: time="2025-05-09T05:44:41+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:41 primo go-librespot[26936]: time="2025-05-09T05:44:41+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:41 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:41 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:44 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:44 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:44 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:44 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:44 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:44 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:44 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2754. May 09 05:44:44 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:44 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:44 primo go-librespot[26948]: Librespot-go daemon starting... May 09 05:44:44 primo go-librespot[26948]: time="2025-05-09T05:44:44+02:00" level=info msg="generated new device id: c0958937947c71358fe1e33e0d989e88308a98da" May 09 05:44:44 primo go-librespot[26948]: time="2025-05-09T05:44:44+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:44 primo go-librespot[26948]: time="2025-05-09T05:44:44+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:44 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:44 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:47 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:47 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:48 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:48 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2755. May 09 05:44:48 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:48 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:48 primo go-librespot[26958]: Librespot-go daemon starting... May 09 05:44:48 primo go-librespot[26958]: time="2025-05-09T05:44:48+02:00" level=info msg="generated new device id: a993001d024c7afe0553685470ff0d0f9904cecd" May 09 05:44:48 primo go-librespot[26958]: time="2025-05-09T05:44:48+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:48 primo go-librespot[26958]: time="2025-05-09T05:44:48+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:48 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:48 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:49 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:49 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:49 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:50 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:50 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:51 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:51 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2756. May 09 05:44:51 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:51 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:51 primo go-librespot[26987]: Librespot-go daemon starting... May 09 05:44:51 primo go-librespot[26987]: time="2025-05-09T05:44:51+02:00" level=info msg="generated new device id: 13fc2b93c563e77ef35c57f2456f92b3da080395" May 09 05:44:51 primo go-librespot[26987]: time="2025-05-09T05:44:51+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:51 primo go-librespot[26987]: time="2025-05-09T05:44:51+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:51 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:51 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:53 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:53 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:54 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:54 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:54 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:44:54 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:54 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2757. May 09 05:44:54 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:54 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:54 primo go-librespot[26999]: Librespot-go daemon starting... May 09 05:44:54 primo go-librespot[26999]: time="2025-05-09T05:44:54+02:00" level=info msg="generated new device id: 299889dd3cf090abae9bddfb74a5668d9029d96e" May 09 05:44:54 primo go-librespot[26999]: time="2025-05-09T05:44:54+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:54 primo go-librespot[26999]: time="2025-05-09T05:44:54+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:54 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:54 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:56 primo ntpd[3074]: error resolving pool 3.debian.pool.ntp.org: System error (-11) May 09 05:44:56 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:56 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:57 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:44:57 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2758. May 09 05:44:57 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:44:57 primo systemd[1]: Started go-librespot Daemon. May 09 05:44:57 primo go-librespot[27009]: Librespot-go daemon starting... May 09 05:44:57 primo go-librespot[27009]: time="2025-05-09T05:44:57+02:00" level=info msg="generated new device id: 437eec5eb6be3a8a447c925723774e3bd8338b01" May 09 05:44:57 primo go-librespot[27009]: time="2025-05-09T05:44:57+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:44:57 primo go-librespot[27009]: time="2025-05-09T05:44:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:44:57 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:44:57 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:44:59 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:44:59 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:44:59 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:44:59 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:44:59 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:01 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:01 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2759. May 09 05:45:01 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:01 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:01 primo go-librespot[27047]: Librespot-go daemon starting... May 09 05:45:01 primo go-librespot[27047]: time="2025-05-09T05:45:01+02:00" level=info msg="generated new device id: affb98fa20502ad73e46ffe4454695c9231d5faf" May 09 05:45:01 primo go-librespot[27047]: time="2025-05-09T05:45:01+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:01 primo go-librespot[27047]: time="2025-05-09T05:45:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:01 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:01 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:02 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:02 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:04 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:04 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2760. May 09 05:45:04 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:04 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:04 primo go-librespot[27054]: Librespot-go daemon starting... May 09 05:45:04 primo go-librespot[27054]: time="2025-05-09T05:45:04+02:00" level=info msg="generated new device id: c5e8b3288f22ff9b13689c709a61f7998a6fc197" May 09 05:45:04 primo go-librespot[27054]: time="2025-05-09T05:45:04+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:04 primo go-librespot[27054]: time="2025-05-09T05:45:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:04 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:04 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:04 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:04 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:04 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:05 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:05 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:07 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:07 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2761. May 09 05:45:07 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:07 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:07 primo go-librespot[27070]: Librespot-go daemon starting... May 09 05:45:07 primo go-librespot[27070]: time="2025-05-09T05:45:07+02:00" level=info msg="generated new device id: 4a0dbf798f6cfbb350aabbfa6d4d9a5e057f9b15" May 09 05:45:07 primo go-librespot[27070]: time="2025-05-09T05:45:07+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:07 primo go-librespot[27070]: time="2025-05-09T05:45:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:07 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:07 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:08 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:08 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:09 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:09 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:09 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:10 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:10 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2762. May 09 05:45:10 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:10 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:10 primo go-librespot[27140]: Librespot-go daemon starting... May 09 05:45:10 primo go-librespot[27140]: time="2025-05-09T05:45:10+02:00" level=info msg="generated new device id: 9f0308805d55a1fb63c191390c7febb5dafd1ce4" May 09 05:45:10 primo go-librespot[27140]: time="2025-05-09T05:45:10+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:10 primo go-librespot[27140]: time="2025-05-09T05:45:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:10 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:10 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:11 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:11 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:14 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:14 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2763. May 09 05:45:14 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:14 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:14 primo go-librespot[27147]: Librespot-go daemon starting... May 09 05:45:14 primo go-librespot[27147]: time="2025-05-09T05:45:14+02:00" level=info msg="generated new device id: e2e808c77c78aa7eb0142e23772e39f8eaff142a" May 09 05:45:14 primo go-librespot[27147]: time="2025-05-09T05:45:14+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:14 primo go-librespot[27147]: time="2025-05-09T05:45:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:14 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:14 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:14 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:14 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:14 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:14 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:14 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:17 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:17 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2764. May 09 05:45:17 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:17 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:17 primo go-librespot[27162]: Librespot-go daemon starting... May 09 05:45:17 primo go-librespot[27162]: time="2025-05-09T05:45:17+02:00" level=info msg="generated new device id: b51a958fe29373e33ab0a05f3080f8644524ce89" May 09 05:45:17 primo go-librespot[27162]: time="2025-05-09T05:45:17+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:17 primo go-librespot[27162]: time="2025-05-09T05:45:17+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:17 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:17 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:17 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:17 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:19 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:19 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:19 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:20 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:20 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:20 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:20 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2765. May 09 05:45:20 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:20 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:20 primo go-librespot[27191]: Librespot-go daemon starting... May 09 05:45:20 primo go-librespot[27191]: time="2025-05-09T05:45:20+02:00" level=info msg="generated new device id: 071f23bbcb673fdbf159ab8ed6359ea99b52e10a" May 09 05:45:20 primo go-librespot[27191]: time="2025-05-09T05:45:20+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:20 primo go-librespot[27191]: time="2025-05-09T05:45:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:20 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:20 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:21 primo ntpd[3074]: error resolving pool 2.debian.pool.ntp.org: System error (-11) May 09 05:45:23 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:23 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:23 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:23 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2766. May 09 05:45:23 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:23 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:23 primo go-librespot[27198]: Librespot-go daemon starting... May 09 05:45:23 primo go-librespot[27198]: time="2025-05-09T05:45:23+02:00" level=info msg="generated new device id: 095d7713114a26c67506a51b1316f311cd302719" May 09 05:45:23 primo go-librespot[27198]: time="2025-05-09T05:45:23+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:23 primo go-librespot[27198]: time="2025-05-09T05:45:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:23 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:23 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:24 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:24 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:24 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:26 primo ntpd[3074]: error resolving pool 1.debian.pool.ntp.org: System error (-11) May 09 05:45:26 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:26 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:27 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:27 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2767. May 09 05:45:27 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:27 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:27 primo go-librespot[27213]: Librespot-go daemon starting... May 09 05:45:27 primo go-librespot[27213]: time="2025-05-09T05:45:27+02:00" level=info msg="generated new device id: e645ab945b1ce5420ee93c79c590d8327397aa17" May 09 05:45:27 primo go-librespot[27213]: time="2025-05-09T05:45:27+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:27 primo go-librespot[27213]: time="2025-05-09T05:45:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:27 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:27 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:29 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:29 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:29 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:29 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:29 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:30 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:30 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2768. May 09 05:45:30 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:30 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:30 primo go-librespot[27243]: Librespot-go daemon starting... May 09 05:45:30 primo go-librespot[27243]: time="2025-05-09T05:45:30+02:00" level=info msg="generated new device id: 0ed684a44971b78870df11794d145e28ab137065" May 09 05:45:30 primo go-librespot[27243]: time="2025-05-09T05:45:30+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:30 primo go-librespot[27243]: time="2025-05-09T05:45:30+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:30 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:30 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: Trying to associate with 38:10:d5:5a:23:4f (SSID='WuenschenGutenTag$_:FsLiPx8Y0_$!' freq=2412 MHz) May 09 05:45:31 primo kernel: [95B blob data] May 09 05:45:31 primo kernel: dhd_dbg_start_pkt_monitor, 1724 May 09 05:45:31 primo kernel: wl_iw_event: Link UP with 38:10:d5:5a:23:4f May 09 05:45:31 primo kernel: wl_bss_connect_done succeeded with 38:10:d5:5a:23:4f May 09 05:45:31 primo kernel: CFG80211-ERROR) wl_cfg80211_scan_abort : scan abort failed May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: Associated with 38:10:d5:5a:23:4f May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=CH May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: WPA: Key negotiation completed with 38:10:d5:5a:23:4f [PTK=CCMP GTK=CCMP] May 09 05:45:31 primo wpa_supplicant[3194]: wlan0: CTRL-EVENT-CONNECTED - Connection to 38:10:d5:5a:23:4f completed [id=0 id_str=] May 09 05:45:31 primo dhcpcd[3409]: wlan0: carrier acquired May 09 05:45:31 primo dhcpcd[3409]: wlan0: IAID 32:e4:4f:a4 May 09 05:45:31 primo kernel: wl_bss_connect_done succeeded with 38:10:d5:5a:23:4f vndr_oui: 8C-FD-F0 May 09 05:45:31 primo kernel: nf_conntrack: default automatic helper assignment has been turned off for security reasons and CT-based firewall rule not found. Use the iptables CT target to attach helpers instead. May 09 05:45:31 primo dhcpcd[3409]: wlan0: soliciting a DHCP lease May 09 05:45:31 primo dhcpcd[3409]: wlan0: offered 192.168.178.106 from 192.168.178.1 May 09 05:45:31 primo dhcpcd[3409]: wlan0: probing address 192.168.178.106/24 May 09 05:45:32 primo dhcpcd[3409]: wlan0: soliciting an IPv6 router May 09 05:45:32 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:32 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:33 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:33 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2769. May 09 05:45:33 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:33 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:33 primo go-librespot[27252]: Librespot-go daemon starting... May 09 05:45:33 primo go-librespot[27252]: time="2025-05-09T05:45:33+02:00" level=info msg="generated new device id: d9c5aedda7111bfc5c62e0a1db39f76899b2bedf" May 09 05:45:33 primo go-librespot[27252]: time="2025-05-09T05:45:33+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:33 primo go-librespot[27252]: time="2025-05-09T05:45:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" May 09 05:45:33 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 05:45:33 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 05:45:34 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:34 primo volumio-time-update[2839]: volumio-time-update-util: Date not found in response May 09 05:45:34 primo volumio-time-update[2839]: volumio-time-update-util: Retrying in 5 seconds... May 09 05:45:35 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:35 primo volumio[3290]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 05:45:36 primo dhcpcd[3409]: wlan0: leased 192.168.178.106 for 86400 seconds May 09 05:45:36 primo avahi-daemon[2837]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.106. May 09 05:45:36 primo dhcpcd[3409]: wlan0: adding route to 192.168.178.0/24 May 09 05:45:36 primo dhcpcd[3409]: wlan0: adding default route via 192.168.178.1 May 09 05:45:36 primo avahi-daemon[2837]: New relevant interface wlan0.IPv4 for mDNS. May 09 05:45:36 primo avahi-daemon[2837]: Registering new address record for 192.168.178.106 on wlan0.IPv4. May 09 05:45:36 primo ntpd[3074]: ntpd exiting on signal 15 (Terminated) May 09 05:45:36 primo systemd[1]: Stopping Network Time Service... May 09 05:45:36 primo volumio[3290]: ------------------------------------ BT MESSAGE: BT STATUS: running May 09 05:45:36 primo systemd[1]: ntp.service: Succeeded. May 09 05:45:36 primo systemd[1]: Stopped Network Time Service. May 09 05:45:36 primo volumio[3290]: ------------------------------------ BT MESSAGE: BT STATUS: waiting May 09 05:45:36 primo systemd[1]: Starting Network Time Service... May 09 05:45:36 primo volumio[3290]: ------------------------------------ BT MESSAGE: BT STATUS: running May 09 05:45:36 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 05:45:36 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2770. May 09 05:45:36 primo systemd[1]: Stopped go-librespot Daemon. May 09 05:45:36 primo systemd[1]: Started go-librespot Daemon. May 09 05:45:36 primo go-librespot[27306]: Librespot-go daemon starting... May 09 05:45:36 primo ntpd[27302]: ntpd 4.2.8p12@1.3728-o (1): Starting May 09 05:45:36 primo ntpd[27302]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 May 09 05:45:36 primo systemd[1]: Started Network Time Service. May 09 05:45:36 primo go-librespot[27306]: time="2025-05-09T05:45:36+02:00" level=info msg="generated new device id: 79c4e3a9a1cf82a3117a737dd3234f49273232e7" May 09 05:45:36 primo go-librespot[27306]: time="2025-05-09T05:45:36+02:00" level=debug msg="stored credentials found for 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:36 primo ntpd[27316]: proto: precision = 1.250 usec (-20) May 09 05:45:36 primo ntpd[27316]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature May 09 05:45:36 primo ntpd[27316]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 May 09 05:45:36 primo ntpd[27316]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 864 days ago May 09 05:45:36 primo ntpd[27316]: Listen and drop on 0 v6wildcard [::]:123 May 09 05:45:36 primo ntpd[27316]: Listen and drop on 1 v4wildcard 0.0.0.0:123 May 09 05:45:36 primo ntpd[27316]: Listen normally on 2 lo 127.0.0.1:123 May 09 05:45:36 primo ntpd[27316]: Listen normally on 3 wlan0 192.168.178.106:123 May 09 05:45:36 primo ntpd[27316]: Listening on routing socket on fd #20 for interface updates May 09 05:45:36 primo ntpd[27316]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized May 09 05:45:36 primo ntpd[27316]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="zeroconf server listening on port 33535" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="obtained new client token: AACgb/yxw0xTAAkXGFLcxTsLwYVJQsQZQYWIbM4ZbPBS0vREyo19/McU6+GW+ScFnDGJkxtKNF6NYlXTfrnp6ZvxFmT9gp7rWh254cSLAig/xc/VMrDCjBSzUhe+YrWZ30ed2u/Dhq/9Il5EwZLSvbWuiUi3HxsxyAPqAgUcormI74uOaUADKCZHdQvu8vBApdE4ZMewD6GkfXtSrjo80lxEDtrnaIndo+blxqN18kgfYbKZ7/3l+fAPYihb" May 09 05:45:37 primo volumio[3290]: info: Discovery: adding 70506f4f-2a69-4c48-b621-5e8927504fdd May 09 05:45:37 primo volumio[3290]: info: Discovery: Found device Primo May 09 05:45:37 primo volumio[3290]: info: CoreCommandRouter::volumioGetState May 09 05:45:37 primo volumio[3290]: info: CorePlayQueue::getTrack 0 May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="completed keyexchange" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="completed challenge" May 09 05:45:37 primo go-librespot[27306]: time="2025-05-09T05:45:37+02:00" level=debug msg="authenticated as 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="authenticated as 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="dealer connection opened" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="initializing zeroconf session, username: 31qqlgjuzufbkztwtnmjq532a37a" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="autoplay enabled: false" May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="received connection id: OTFkOWE1ODMtZTdkNC00YWNhLThjM2ItYzcwZDczOWUyZDA1K2RlYWxlcit0Y3A6Ly8wYWNhNTliOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArREExQjA0MENGRkY2RDcxMTVEMzZFRUM3MkRGM0JCM0NGRDhCQjk0NUEzMTg4QzBGRTIwNjcwOUVDN0FDQ0I0RA==" May 09 05:45:38 primo ntpd[27316]: Soliciting pool server 195.186.1.100 May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="put connect state because NEW_DEVICE" May 09 05:45:38 primo volumio[3290]: info: Initializing connection to go-librespot Websocket May 09 05:45:38 primo go-librespot[27306]: time="2025-05-09T05:45:38+02:00" level=debug msg="new websocket client" May 09 05:45:38 primo volumio[3290]: info: Connection to go-librespot Websocket established May 09 05:45:38 primo ntpd[27316]: Soliciting pool server 85.195.227.70 May 09 05:45:38 primo ntpd[27316]: Soliciting pool server 194.56.188.142 May 09 05:45:39 primo volumio[3290]: info: Reporting MCU Network Status: 2 May 09 05:45:39 primo volumio[3290]: info: Volumio Network Manager: Network status updated: 2 May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 09 05:45:39 primo volumio[3290]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 09 05:45:39 primo ntpd[27316]: Soliciting pool server 212.25.15.128 May 09 05:45:39 primo ntpd[27316]: Soliciting pool server 62.12.173.12 May 09 05:45:39 primo volumio-time-update[2839]: volumio-time-update-util: Fetching time from Volumio... May 09 05:45:39 primo ntpd[27316]: Soliciting pool server 217.147.223.78 May 09 05:45:39 primo volumio-time-update[2839]: volumio-time-update-util: Setting system time to: 2025-05-09 05:45:39 May 09 05:45:39 primo sudo[27341]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-05-09 05:45:39 May 09 05:45:39 primo sudo[27341]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 05:45:39 primo dbus-daemon[2842]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.43' (uid=0 pid=27342 comm="timedatectl set-time 2025-05-09 05:45:39 " label="kernel") May 09 05:45:40 primo systemd[1]: Starting Time & Date Service... May 09 05:45:40 primo ntpd[27316]: Soliciting pool server 156.106.214.52 May 09 05:45:40 primo ntpd[27316]: Soliciting pool server 80.242.192.230 May 09 05:45:40 primo ntpd[27316]: Soliciting pool server 62.220.129.71 May 09 05:45:40 primo ntpd[27316]: Soliciting pool server 192.33.214.57 May 09 05:45:41 primo volumio[3290]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 09 05:45:41 primo volumio[3290]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 09 05:45:41 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 05:45:41 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 05:45:41 primo volumio[3290]: info: Starting MyVolumio Remote Streaming Endpoints May 09 05:45:41 primo volumio[3290]: info: MyVolumio login type: Token May 09 05:45:41 primo volumio[3290]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 09 05:45:41 primo volumio[3290]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' May 09 05:45:41 primo volumio[3290]: info: Getting Spotify volume May 09 05:45:41 primo volumio[3290]: ------------------------------------ BT MESSAGE: BT STATUS: running May 09 05:45:41 primo volumio[3290]: info: Spotify volume: 100 May 09 05:45:41 primo volumio[3290]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 09 05:45:41 primo volumio[3290]: info: CoreCommandRouter::volumioGetState May 09 05:45:41 primo volumio[3290]: info: CorePlayQueue::getTrack 0 May 09 05:45:41 primo volumio[3290]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 May 09 05:45:41 primo volumio[3290]: SPOTIFY: SPOTIFY VOLUME 100 May 09 05:45:41 primo ntpd[27316]: Soliciting pool server 193.33.30.39 May 09 05:45:41 primo volumio[3290]: SPOTIFY: VOLUMIO VOLUME 0 May 09 05:45:41 primo volumio[3290]: SPOTIFY: DELTA VOLUME ENOUGH: true May 09 05:45:41 primo volumio[3290]: info: Setting Spotify Volume from Volumio: 0 May 09 05:45:41 primo ntpd[27316]: Soliciting pool server 156.106.214.48 May 09 05:45:41 primo ntpd[27316]: Soliciting pool server 31.3.135.232 May 09 05:45:41 primo volumio[3290]: error: MyVolumio Custom Token format not valid, refreshing it May 09 05:45:42 primo volumio[3290]: info: MyVolumio login type: Token May 09 05:45:42 primo ntpd[27316]: Soliciting pool server 84.254.80.94 May 09 05:45:42 primo ntpd[27316]: Soliciting pool server 84.16.67.12 May 09 05:45:42 primo volumio[3290]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 09 05:45:43 primo volumio[3290]: SPOTIFY: SETTING SPOTIFY VOLUME 0 May 09 05:45:43 primo volumio[3290]: info: Sending Spotify command with payload to local API: /player/volume May 09 05:45:43 primo go-librespot[27306]: time="2025-05-09T05:45:43+02:00" level=debug msg="update volume to 0/65535" May 09 05:45:43 primo volumio[3290]: info: MyVolumio token set successfully May 09 05:45:43 primo volumio[3290]: info: MYVOLUMIO: Adding device May 09 05:45:43 primo volumio[3290]: info: MYVOLUMIO: Evaluating Server May 09 05:45:43 primo go-librespot[27306]: time="2025-05-09T05:45:43+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 09 05:45:43 primo go-librespot[27306]: time="2025-05-09T05:45:43+02:00" level=trace msg="emitting websocket event: volume" May 09 05:45:43 primo volumio[3290]: SPOTIFY: received: {"type":"volume","data":{"value":0,"max":100}} May 09 05:45:43 primo volumio[3290]: SPOTIFY: RECEIVED SPOTIFY VOLUME 0 May 09 05:45:43 primo ntpd[27316]: Soliciting pool server 81.94.123.16 May 09 05:45:43 primo ntpd[27316]: Soliciting pool server 2001:1600:4:1::f May 09 05:45:43 primo dbus-daemon[2842]: [system] Successfully activated service 'org.freedesktop.timedate1' May 09 05:45:43 primo systemd[1]: Started Time & Date Service. May 09 05:45:39 primo systemd-timedated[27343]: Changed local time to Fri May 9 05:45:39 2025 May 09 05:45:39 primo systemd[1]: Started Volumio Time Update Utility. May 09 05:45:39 primo volumio-time-update[2839]: volumio-time-update-util: System time updated successfully. May 09 05:45:39 primo sudo[27341]: pam_unix(sudo:session): session closed for user root May 09 05:45:39 primo systemd[1]: Reached target Multi-User System. May 09 05:45:39 primo systemd[1]: Reached target Graphical Interface. May 09 05:45:39 primo systemd[1]: Starting Update UTMP about System Runlevel Changes... May 09 05:45:39 primo systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 09 05:45:39 primo systemd[1]: Started Update UTMP about System Runlevel Changes. May 09 05:45:39 primo systemd[1]: Startup finished in 12.919s (kernel) + 2h 31min 11.718s (userspace) = 2h 31min 24.638s. May 09 05:45:39 primo volumio[3290]: info: MyVolumio status changed May 09 05:45:39 primo volumio[3290]: info: Streaming services startup May 09 05:45:39 primo volumio[3290]: info: Starting Streaming Daemon May 09 05:45:39 primo volumio[3290]: info: Removing browser output: myVolumio user plan is not superstar May 09 05:45:39 primo volumio[3290]: info: Removing audio output: May 09 05:45:39 primo volumio[3290]: info: Stoppping Tunnel 1 May 09 05:45:39 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 09 05:45:39 primo volumio[3290]: info: Received Get System Info May 09 05:45:39 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 09 05:45:39 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 09 05:45:39 primo volumio[3290]: info: Discovery: Getting this device information May 09 05:45:39 primo volumio[3290]: info: CoreCommandRouter::volumioGetState May 09 05:45:39 primo volumio[3290]: info: CorePlayQueue::getTrack 0 May 09 05:45:39 primo volumio[3290]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 09 05:45:39 primo sudo[27368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 09 05:45:39 primo sudo[27370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service May 09 05:45:39 primo sudo[27370]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 05:45:39 primo sudo[27368]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 05:45:39 primo volumio[3290]: ------------------------------------ BT MESSAGE: BT STATUS: running May 09 05:45:39 primo volumio[3290]: error: Failed to ping endpoint us1.myvolumio.org : unknown error May 09 05:45:39 primo volumio[3290]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 05:45:39 primo volumio[3290]: Error: Unable to resolve or reject the same promise twice May 09 05:45:39 primo volumio[3290]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) May 09 05:45:39 primo volumio[3290]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32367) May 09 05:45:39 primo volumio[3290]: at Socket.emit (events.js:400:28) May 09 05:45:39 primo volumio[3290]: at addChunk (internal/streams/readable.js:293:12) May 09 05:45:39 primo volumio[3290]: at readableAddChunk (internal/streams/readable.js:267:9) May 09 05:45:39 primo volumio[3290]: at Socket.Readable.push (internal/streams/readable.js:206:10) May 09 05:45:39 primo volumio[3290]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) May 09 05:45:39 primo volumio[3290]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 05:45:39 primo sudo[27368]: pam_unix(sudo:session): session closed for user root May 09 05:45:39 primo sudo[27370]: pam_unix(sudo:session): session closed for user root May 09 05:45:39 primo sudo[27383]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-09 05:44 May 09 05:45:39 primo sudo[27383]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 05:41:47 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="d050b972c82ad0b26840d04dc6ef55b1"