-- Logs begin at Wed 2025-04-30 05:18:51 EEST, end at Wed 2025-04-30 06:19:10 EEST. -- Apr 30 06:18:00 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:00 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1080. Apr 30 06:18:00 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:00 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:00 primo go-librespot[25288]: go-librespot daemon starting... Apr 30 06:18:00 primo go-librespot[25288]: time="2025-04-30T06:18:00+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:00 primo go-librespot[25288]: time="2025-04-30T06:18:00+03:00" level=debug msg="app state loaded" Apr 30 06:18:00 primo go-librespot[25288]: time="2025-04-30T06:18:00+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:00 primo go-librespot[25288]: time="2025-04-30T06:18:00+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:00 primo go-librespot[25288]: time="2025-04-30T06:18:00+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:00 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:00 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:01 primo ntpd[3251]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Apr 30 06:18:01 primo ntpd[3251]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 30 06:18:02 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:02 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:03 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:03 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1081. Apr 30 06:18:03 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:03 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:03 primo go-librespot[25298]: go-librespot daemon starting... Apr 30 06:18:03 primo go-librespot[25298]: time="2025-04-30T06:18:03+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:03 primo go-librespot[25298]: time="2025-04-30T06:18:03+03:00" level=debug msg="app state loaded" Apr 30 06:18:03 primo go-librespot[25298]: time="2025-04-30T06:18:03+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:03 primo go-librespot[25298]: time="2025-04-30T06:18:03+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:03 primo go-librespot[25298]: time="2025-04-30T06:18:03+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:03 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:03 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:04 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:04 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:04 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:05 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:05 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:06 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:06 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1082. Apr 30 06:18:06 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:06 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:06 primo go-librespot[25336]: go-librespot daemon starting... Apr 30 06:18:06 primo go-librespot[25336]: time="2025-04-30T06:18:06+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:06 primo go-librespot[25336]: time="2025-04-30T06:18:06+03:00" level=debug msg="app state loaded" Apr 30 06:18:06 primo go-librespot[25336]: time="2025-04-30T06:18:06+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:06 primo go-librespot[25336]: time="2025-04-30T06:18:06+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:06 primo go-librespot[25336]: time="2025-04-30T06:18:06+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:06 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:06 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:08 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:08 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:09 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:09 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:09 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:09 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:09 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1083. Apr 30 06:18:09 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:09 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:09 primo go-librespot[25386]: go-librespot daemon starting... Apr 30 06:18:09 primo go-librespot[25386]: time="2025-04-30T06:18:09+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:09 primo go-librespot[25386]: time="2025-04-30T06:18:09+03:00" level=debug msg="app state loaded" Apr 30 06:18:09 primo go-librespot[25386]: time="2025-04-30T06:18:09+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:09 primo go-librespot[25386]: time="2025-04-30T06:18:09+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:09 primo go-librespot[25386]: time="2025-04-30T06:18:09+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:09 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:09 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:11 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:11 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:13 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:13 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1084. Apr 30 06:18:13 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:13 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:13 primo go-librespot[25394]: go-librespot daemon starting... Apr 30 06:18:13 primo go-librespot[25394]: time="2025-04-30T06:18:13+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:13 primo go-librespot[25394]: time="2025-04-30T06:18:13+03:00" level=debug msg="app state loaded" Apr 30 06:18:13 primo go-librespot[25394]: time="2025-04-30T06:18:13+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:13 primo go-librespot[25394]: time="2025-04-30T06:18:13+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:13 primo go-librespot[25394]: time="2025-04-30T06:18:13+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:13 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:13 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:14 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:14 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:14 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:14 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:14 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:16 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:16 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1085. Apr 30 06:18:16 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:16 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:16 primo go-librespot[25423]: go-librespot daemon starting... Apr 30 06:18:16 primo go-librespot[25423]: time="2025-04-30T06:18:16+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:16 primo go-librespot[25423]: time="2025-04-30T06:18:16+03:00" level=debug msg="app state loaded" Apr 30 06:18:16 primo go-librespot[25423]: time="2025-04-30T06:18:16+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:16 primo go-librespot[25423]: time="2025-04-30T06:18:16+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:16 primo go-librespot[25423]: time="2025-04-30T06:18:16+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:16 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:16 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:17 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:17 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:19 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:19 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:19 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:19 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:19 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1086. Apr 30 06:18:19 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:19 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:19 primo go-librespot[25435]: go-librespot daemon starting... Apr 30 06:18:19 primo go-librespot[25435]: time="2025-04-30T06:18:19+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:19 primo go-librespot[25435]: time="2025-04-30T06:18:19+03:00" level=debug msg="app state loaded" Apr 30 06:18:19 primo go-librespot[25435]: time="2025-04-30T06:18:19+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:19 primo go-librespot[25435]: time="2025-04-30T06:18:19+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:19 primo go-librespot[25435]: time="2025-04-30T06:18:19+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:19 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:19 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:20 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:20 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:22 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:22 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1087. Apr 30 06:18:22 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:22 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:22 primo go-librespot[25442]: go-librespot daemon starting... Apr 30 06:18:22 primo go-librespot[25442]: time="2025-04-30T06:18:22+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:22 primo go-librespot[25442]: time="2025-04-30T06:18:22+03:00" level=debug msg="app state loaded" Apr 30 06:18:22 primo go-librespot[25442]: time="2025-04-30T06:18:22+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:22 primo go-librespot[25442]: time="2025-04-30T06:18:22+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:22 primo go-librespot[25442]: time="2025-04-30T06:18:22+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:22 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:22 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:23 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:23 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:24 primo ntpd[3251]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Apr 30 06:18:24 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:24 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:24 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:26 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:26 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1088. Apr 30 06:18:26 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:26 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:26 primo go-librespot[25476]: go-librespot daemon starting... Apr 30 06:18:26 primo go-librespot[25476]: time="2025-04-30T06:18:26+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:26 primo go-librespot[25476]: time="2025-04-30T06:18:26+03:00" level=debug msg="app state loaded" Apr 30 06:18:26 primo go-librespot[25476]: time="2025-04-30T06:18:26+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:26 primo go-librespot[25476]: time="2025-04-30T06:18:26+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:26 primo go-librespot[25476]: time="2025-04-30T06:18:26+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:26 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:26 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:26 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:26 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:29 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:29 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1089. Apr 30 06:18:29 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:29 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:29 primo go-librespot[25484]: go-librespot daemon starting... Apr 30 06:18:29 primo go-librespot[25484]: time="2025-04-30T06:18:29+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:29 primo go-librespot[25484]: time="2025-04-30T06:18:29+03:00" level=debug msg="app state loaded" Apr 30 06:18:29 primo go-librespot[25484]: time="2025-04-30T06:18:29+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:29 primo go-librespot[25484]: time="2025-04-30T06:18:29+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:29 primo go-librespot[25484]: time="2025-04-30T06:18:29+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:29 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:29 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:29 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:29 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:29 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:29 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:29 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:32 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:32 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1090. Apr 30 06:18:32 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:32 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:32 primo go-librespot[25505]: go-librespot daemon starting... Apr 30 06:18:32 primo go-librespot[25505]: time="2025-04-30T06:18:32+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:32 primo go-librespot[25505]: time="2025-04-30T06:18:32+03:00" level=debug msg="app state loaded" Apr 30 06:18:32 primo go-librespot[25505]: time="2025-04-30T06:18:32+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:32 primo go-librespot[25505]: time="2025-04-30T06:18:32+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:32 primo go-librespot[25505]: time="2025-04-30T06:18:32+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:32 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:32 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:32 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:32 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:34 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:34 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:34 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:35 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:35 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1091. Apr 30 06:18:35 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:35 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:35 primo go-librespot[25534]: go-librespot daemon starting... Apr 30 06:18:35 primo go-librespot[25534]: time="2025-04-30T06:18:35+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:35 primo go-librespot[25534]: time="2025-04-30T06:18:35+03:00" level=debug msg="app state loaded" Apr 30 06:18:35 primo go-librespot[25534]: time="2025-04-30T06:18:35+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:35 primo go-librespot[25534]: time="2025-04-30T06:18:35+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:35 primo go-librespot[25534]: time="2025-04-30T06:18:35+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:35 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:35 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:35 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:35 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:38 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:38 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:39 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:39 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1092. Apr 30 06:18:39 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:39 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:39 primo go-librespot[25543]: go-librespot daemon starting... Apr 30 06:18:39 primo go-librespot[25543]: time="2025-04-30T06:18:39+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:39 primo go-librespot[25543]: time="2025-04-30T06:18:39+03:00" level=debug msg="app state loaded" Apr 30 06:18:39 primo go-librespot[25543]: time="2025-04-30T06:18:39+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:39 primo go-librespot[25543]: time="2025-04-30T06:18:39+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:39 primo go-librespot[25543]: time="2025-04-30T06:18:39+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:39 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:39 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:39 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:39 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:39 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:41 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:41 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:42 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:42 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1093. Apr 30 06:18:42 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:42 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:42 primo go-librespot[25556]: go-librespot daemon starting... Apr 30 06:18:42 primo go-librespot[25556]: time="2025-04-30T06:18:42+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:42 primo go-librespot[25556]: time="2025-04-30T06:18:42+03:00" level=debug msg="app state loaded" Apr 30 06:18:42 primo go-librespot[25556]: time="2025-04-30T06:18:42+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:42 primo go-librespot[25556]: time="2025-04-30T06:18:42+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:42 primo go-librespot[25556]: time="2025-04-30T06:18:42+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:42 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:42 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:44 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:44 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:44 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:45 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:45 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:45 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:45 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1094. Apr 30 06:18:45 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:45 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:45 primo go-librespot[25588]: go-librespot daemon starting... Apr 30 06:18:45 primo go-librespot[25588]: time="2025-04-30T06:18:45+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:45 primo go-librespot[25588]: time="2025-04-30T06:18:45+03:00" level=debug msg="app state loaded" Apr 30 06:18:45 primo go-librespot[25588]: time="2025-04-30T06:18:45+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:45 primo go-librespot[25588]: time="2025-04-30T06:18:45+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:45 primo go-librespot[25588]: time="2025-04-30T06:18:45+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:45 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:45 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:48 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:48 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:48 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:48 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1095. Apr 30 06:18:48 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:48 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:48 primo go-librespot[25595]: go-librespot daemon starting... Apr 30 06:18:48 primo go-librespot[25595]: time="2025-04-30T06:18:48+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:48 primo go-librespot[25595]: time="2025-04-30T06:18:48+03:00" level=debug msg="app state loaded" Apr 30 06:18:48 primo go-librespot[25595]: time="2025-04-30T06:18:48+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:48 primo go-librespot[25595]: time="2025-04-30T06:18:48+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:48 primo go-librespot[25595]: time="2025-04-30T06:18:48+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:48 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:48 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:49 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:49 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:49 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:51 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:51 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:51 primo ntpd[3251]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 30 06:18:52 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:52 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1096. Apr 30 06:18:52 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:52 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:52 primo go-librespot[25609]: go-librespot daemon starting... Apr 30 06:18:52 primo go-librespot[25609]: time="2025-04-30T06:18:52+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:52 primo go-librespot[25609]: time="2025-04-30T06:18:52+03:00" level=debug msg="app state loaded" Apr 30 06:18:52 primo go-librespot[25609]: time="2025-04-30T06:18:52+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:52 primo go-librespot[25609]: time="2025-04-30T06:18:52+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:52 primo go-librespot[25609]: time="2025-04-30T06:18:52+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:52 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:52 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:54 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:54 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:54 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:54 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:54 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:18:55 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:55 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1097. Apr 30 06:18:55 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:55 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:55 primo go-librespot[25639]: go-librespot daemon starting... Apr 30 06:18:55 primo go-librespot[25639]: time="2025-04-30T06:18:55+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:55 primo go-librespot[25639]: time="2025-04-30T06:18:55+03:00" level=debug msg="app state loaded" Apr 30 06:18:55 primo go-librespot[25639]: time="2025-04-30T06:18:55+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:55 primo go-librespot[25639]: time="2025-04-30T06:18:55+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:55 primo go-librespot[25639]: time="2025-04-30T06:18:55+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:55 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:55 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:57 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:18:57 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:18:58 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:18:58 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1098. Apr 30 06:18:58 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:18:58 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:18:58 primo go-librespot[25649]: go-librespot daemon starting... Apr 30 06:18:58 primo go-librespot[25649]: time="2025-04-30T06:18:58+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:18:58 primo go-librespot[25649]: time="2025-04-30T06:18:58+03:00" level=debug msg="app state loaded" Apr 30 06:18:58 primo go-librespot[25649]: time="2025-04-30T06:18:58+03:00" level=debug msg="stored credentials not found" Apr 30 06:18:58 primo go-librespot[25649]: time="2025-04-30T06:18:58+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:18:58 primo go-librespot[25649]: time="2025-04-30T06:18:58+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:18:58 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:18:58 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:18:59 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:18:59 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:18:59 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:19:00 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:19:00 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:19:01 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:19:01 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1099. Apr 30 06:19:01 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:19:01 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:19:01 primo go-librespot[25661]: go-librespot daemon starting... Apr 30 06:19:01 primo go-librespot[25661]: time="2025-04-30T06:19:01+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:19:01 primo go-librespot[25661]: time="2025-04-30T06:19:01+03:00" level=debug msg="app state loaded" Apr 30 06:19:01 primo go-librespot[25661]: time="2025-04-30T06:19:01+03:00" level=debug msg="stored credentials not found" Apr 30 06:19:01 primo go-librespot[25661]: time="2025-04-30T06:19:01+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:19:01 primo go-librespot[25661]: time="2025-04-30T06:19:01+03:00" level=fatal msg="failed running zeroconf" 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" Apr 30 06:19:01 primo systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 30 06:19:01 primo systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 30 06:19:03 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:19:03 primo volumio[3100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 30 06:19:04 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:19:04 primo volumio-time-update[2824]: volumio-time-update-util: Date not found in response Apr 30 06:19:04 primo volumio-time-update[2824]: volumio-time-update-util: Retrying in 5 seconds... Apr 30 06:19:04 primo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 30 06:19:04 primo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1100. Apr 30 06:19:04 primo systemd[1]: Stopped go-librespot Daemon. Apr 30 06:19:04 primo systemd[1]: Started go-librespot Daemon. Apr 30 06:19:04 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 30 06:19:04 primo go-librespot[25734]: go-librespot daemon starting... Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=info msg="running go-librespot 0.2.0" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=debug msg="app state loaded" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=debug msg="stored credentials not found" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 30 06:19:05 primo ntpd[3251]: ntpd exiting on signal 15 (Terminated) Apr 30 06:19:05 primo systemd[1]: Stopping Network Time Service... Apr 30 06:19:05 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 30 06:19:05 primo systemd[1]: ntp.service: Succeeded. Apr 30 06:19:05 primo systemd[1]: Stopped Network Time Service. Apr 30 06:19:05 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 30 06:19:05 primo systemd[1]: Starting Network Time Service... Apr 30 06:19:05 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 30 06:19:05 primo ntpd[25765]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 30 06:19:05 primo ntpd[25765]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Apr 30 06:19:05 primo systemd[1]: Started Network Time Service. Apr 30 06:19:05 primo ntpd[25771]: proto: precision = 1.250 usec (-20) Apr 30 06:19:05 primo ntpd[25771]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 30 06:19:05 primo ntpd[25771]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 30 06:19:05 primo ntpd[25771]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 855 days ago Apr 30 06:19:05 primo ntpd[25771]: Listen and drop on 0 v6wildcard [::]:123 Apr 30 06:19:05 primo ntpd[25771]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 30 06:19:05 primo ntpd[25771]: Listen normally on 2 lo 127.0.0.1:123 Apr 30 06:19:05 primo ntpd[25771]: Listen normally on 3 eth0 192.168.0.100:123 Apr 30 06:19:05 primo ntpd[25771]: Listening on routing socket on fd #20 for interface updates Apr 30 06:19:05 primo ntpd[25771]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Apr 30 06:19:05 primo ntpd[25771]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Apr 30 06:19:05 primo go-librespot[25734]: time="2025-04-30T06:19:05+03:00" level=info msg="zeroconf server listening on port 44557" Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 30 06:19:05 primo volumio[3100]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 30 06:19:06 primo ntpd[25771]: Soliciting pool server 176.117.185.230 Apr 30 06:19:07 primo volumio[3100]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 30 06:19:07 primo volumio[3100]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 30 06:19:07 primo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 30 06:19:07 primo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 30 06:19:07 primo volumio[3100]: info: Starting MyVolumio Remote Streaming Endpoints Apr 30 06:19:07 primo volumio[3100]: info: MyVolumio login type: Token Apr 30 06:19:07 primo volumio[3100]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 30 06:19:07 primo volumio[3100]: 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' Apr 30 06:19:07 primo ntpd[25771]: Soliciting pool server 91.236.251.234 Apr 30 06:19:07 primo volumio[3100]: info: Initializing connection to go-librespot Websocket Apr 30 06:19:07 primo go-librespot[25734]: time="2025-04-30T06:19:07+03:00" level=debug msg="new websocket client" Apr 30 06:19:07 primo volumio[3100]: info: Connection to go-librespot Websocket established Apr 30 06:19:07 primo ntpd[25771]: Soliciting pool server 194.8.146.38 Apr 30 06:19:07 primo volumio[3100]: error: MyVolumio Custom Token format not valid, refreshing it Apr 30 06:19:08 primo ntpd[25771]: Soliciting pool server 217.12.206.12 Apr 30 06:19:08 primo ntpd[25771]: Soliciting pool server 91.236.251.35 Apr 30 06:19:08 primo ntpd[25771]: Soliciting pool server 194.54.80.29 Apr 30 06:19:08 primo volumio[3100]: info: MyVolumio login type: Token Apr 30 06:19:09 primo volumio[3100]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Apr 30 06:19:09 primo ntpd[25771]: Soliciting pool server 162.159.200.123 Apr 30 06:19:09 primo ntpd[25771]: Soliciting pool server 91.231.182.17 Apr 30 06:19:09 primo ntpd[25771]: Soliciting pool server 91.236.251.38 Apr 30 06:19:09 primo ntpd[25771]: Soliciting pool server 193.106.144.6 Apr 30 06:19:09 primo volumio[3100]: info: MyVolumio token set successfully Apr 30 06:19:09 primo volumio[3100]: info: MYVOLUMIO: Adding device Apr 30 06:19:09 primo volumio[3100]: info: MYVOLUMIO: Evaluating Server Apr 30 06:19:09 primo volumio-time-update[2824]: volumio-time-update-util: Fetching time from Volumio... Apr 30 06:19:10 primo volumio-time-update[2824]: volumio-time-update-util: Setting system time to: 2025-04-30 06:19:08 Apr 30 06:19:10 primo sudo[25837]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-04-30 06:19:08 Apr 30 06:19:10 primo sudo[25837]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 30 06:19:10 primo dbus-daemon[2828]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.40' (uid=0 pid=25840 comm="timedatectl set-time 2025-04-30 06:19:08 " label="kernel") Apr 30 06:19:10 primo systemd[1]: Starting Time & Date Service... Apr 30 06:19:10 primo volumio[3100]: info: MyVolumio status changed Apr 30 06:19:10 primo volumio[3100]: info: Streaming services startup Apr 30 06:19:10 primo volumio[3100]: info: Starting Streaming Daemon Apr 30 06:19:10 primo volumio[3100]: info: Removing browser output: myVolumio user plan is not superstar Apr 30 06:19:10 primo volumio[3100]: info: Removing audio output: Apr 30 06:19:10 primo volumio[3100]: info: Stoppping Tunnel 1 Apr 30 06:19:10 primo sudo[25849]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 30 06:19:10 primo sudo[25849]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 30 06:19:10 primo sudo[25849]: pam_unix(sudo:session): session closed for user root Apr 30 06:19:10 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 30 06:19:10 primo sudo[25852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Apr 30 06:19:10 primo sudo[25852]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 30 06:19:10 primo ntpd[25771]: Soliciting pool server 193.106.144.7 Apr 30 06:19:10 primo ntpd[25771]: Soliciting pool server 62.205.159.155 Apr 30 06:19:10 primo ntpd[25771]: Soliciting pool server 91.236.251.5 Apr 30 06:19:10 primo volumio[3100]: error: Cannot start Volumio Streaming Daemon Apr 30 06:19:10 primo volumio[3100]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 30 06:19:10 primo volumio[3100]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 30 06:19:10 primo sudo[25852]: pam_unix(sudo:session): session closed for user root Apr 30 06:19:10 primo dbus-daemon[2828]: [system] Successfully activated service 'org.freedesktop.timedate1' Apr 30 06:19:10 primo systemd[1]: Started Time & Date Service. Apr 30 06:19:10 primo volumio[3100]: info: Getting Spotify volume Apr 30 06:19:08 primo systemd-timedated[25843]: Changed local time to Wed Apr 30 06:19:08 2025 Apr 30 06:19:08 primo volumio[3100]: info: Remote SSH Stopped Apr 30 06:19:08 primo sudo[25837]: pam_unix(sudo:session): session closed for user root Apr 30 06:19:08 primo volumio-time-update[2824]: volumio-time-update-util: System time updated successfully. Apr 30 06:19:08 primo systemd[1]: Started Volumio Time Update Utility. Apr 30 06:19:08 primo systemd[1]: Reached target Multi-User System. Apr 30 06:19:08 primo systemd[1]: Reached target Graphical Interface. Apr 30 06:19:08 primo systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 30 06:19:08 primo volumio[3100]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 30 06:19:08 primo volumio[3100]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Apr 30 06:19:08 primo systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 30 06:19:08 primo volumio[3100]: info: CoreCommandRouter::volumioGetState Apr 30 06:19:08 primo volumio[3100]: info: CorePlayQueue::getTrack 0 Apr 30 06:19:08 primo systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 30 06:19:08 primo systemd[1]: Startup finished in 12.944s (kernel) + 1h 19.230s (userspace) = 1h 32.174s. Apr 30 06:19:08 primo volumio[3100]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Apr 30 06:19:08 primo volumio[3100]: error: Failed to ping endpoint au1.myvolumio.org : unknown error Apr 30 06:19:08 primo volumio[3100]: info: Setting Geolocation for MyVolumio to eu10 Apr 30 06:19:08 primo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 30 06:19:08 primo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 30 06:19:08 primo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 30 06:19:08 primo volumio[3100]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 30 06:19:08 primo volumio[3100]: Error: Unable to resolve or reject the same promise twice Apr 30 06:19:08 primo volumio[3100]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 30 06:19:08 primo volumio[3100]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32086) Apr 30 06:19:08 primo volumio[3100]: at Socket.emit (events.js:412:35) Apr 30 06:19:08 primo volumio[3100]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 30 06:19:08 primo volumio[3100]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 30 06:19:08 primo volumio[3100]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 30 06:19:08 primo sudo[25867]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-30 06:18 Apr 30 06:19:08 primo sudo[25867]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 30 06:19:08 primo ntpd[25771]: Soliciting pool server 31.28.161.68 Apr 30 06:19:08 primo ntpd[25771]: Soliciting pool server 91.236.251.14 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 24 Apr 2025 11:18:05 AM CEST" VOLUMIO_VERSION="3.804" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="9f695e75406efaab23b5cd362456a567"