-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2025-09-09 16:58:16 CEST. -- Sep 09 16:57:02 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:02 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:02 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:02 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:02 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:02 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:02 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. Sep 09 16:57:02 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:02 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:02 volumioho go-librespot[2498]: go-librespot daemon starting... Sep 09 16:57:02 volumioho go-librespot[2498]: time="2025-09-09T16:57:02+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:02 volumioho go-librespot[2498]: time="2025-09-09T16:57:02+02:00" level=debug msg="app state loaded" Sep 09 16:57:02 volumioho go-librespot[2498]: time="2025-09-09T16:57:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:02 volumioho go-librespot[2498]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:02 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:02 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:05 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:05 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:05 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:05 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. Sep 09 16:57:05 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:05 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:05 volumioho go-librespot[2505]: go-librespot daemon starting... Sep 09 16:57:05 volumioho go-librespot[2505]: time="2025-09-09T16:57:05+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:05 volumioho go-librespot[2505]: time="2025-09-09T16:57:05+02:00" level=debug msg="app state loaded" Sep 09 16:57:05 volumioho go-librespot[2505]: time="2025-09-09T16:57:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:05 volumioho go-librespot[2505]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:05 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:05 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:07 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:07 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:07 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:08 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:08 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:08 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:08 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Sep 09 16:57:08 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:09 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:09 volumioho go-librespot[2535]: go-librespot daemon starting... Sep 09 16:57:09 volumioho go-librespot[2535]: time="2025-09-09T16:57:09+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:09 volumioho go-librespot[2535]: time="2025-09-09T16:57:09+02:00" level=debug msg="app state loaded" Sep 09 16:57:09 volumioho go-librespot[2535]: time="2025-09-09T16:57:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:09 volumioho go-librespot[2535]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:09 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:09 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:11 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:11 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:12 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:12 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. Sep 09 16:57:12 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:12 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:12 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:12 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:12 volumioho go-librespot[2542]: go-librespot daemon starting... Sep 09 16:57:12 volumioho go-librespot[2542]: time="2025-09-09T16:57:12+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:12 volumioho go-librespot[2542]: time="2025-09-09T16:57:12+02:00" level=debug msg="app state loaded" Sep 09 16:57:12 volumioho go-librespot[2542]: time="2025-09-09T16:57:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:12 volumioho go-librespot[2542]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:12 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:12 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:12 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:12 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:12 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:13 volumioho volumio[976]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 09 16:57:13 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Sep 09 16:57:13 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Sep 09 16:57:13 volumioho sudo[2558]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Sep 09 16:57:13 volumioho sudo[2558]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho sudo[2558]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho sudo[2564]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 09 16:57:13 volumioho sudo[2564]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho sudo[2564]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho sudo[2571]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 09 16:57:13 volumioho sudo[2576]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Sep 09 16:57:13 volumioho sudo[2571]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho sudo[2576]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho sudo[2571]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho sudo[2576]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho sudo[2584]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 09 16:57:13 volumioho sudo[2584]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache Sep 09 16:57:13 volumioho sudo[2584]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks Sep 09 16:57:13 volumioho sudo[2586]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 09 16:57:13 volumioho sudo[2586]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:13 volumioho sudo[2586]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:13 volumioho sudo[2590]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 09 16:57:13 volumioho sudo[2590]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:14 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:14 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:14 volumioho sudo[2590]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:15 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:15 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. Sep 09 16:57:15 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:15 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:15 volumioho go-librespot[2592]: go-librespot daemon starting... Sep 09 16:57:15 volumioho go-librespot[2592]: time="2025-09-09T16:57:15+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:15 volumioho go-librespot[2592]: time="2025-09-09T16:57:15+02:00" level=debug msg="app state loaded" Sep 09 16:57:15 volumioho go-librespot[2592]: time="2025-09-09T16:57:15+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:15 volumioho go-librespot[2592]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:15 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:15 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:17 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:17 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:17 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:17 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:17 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:18 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:18 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. Sep 09 16:57:18 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:18 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:18 volumioho go-librespot[2618]: go-librespot daemon starting... Sep 09 16:57:18 volumioho go-librespot[2618]: time="2025-09-09T16:57:18+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:18 volumioho go-librespot[2618]: time="2025-09-09T16:57:18+02:00" level=debug msg="app state loaded" Sep 09 16:57:18 volumioho go-librespot[2618]: time="2025-09-09T16:57:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:18 volumioho go-librespot[2618]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:18 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:18 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:20 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:20 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:21 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:21 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. Sep 09 16:57:21 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:21 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:21 volumioho go-librespot[2663]: go-librespot daemon starting... Sep 09 16:57:21 volumioho go-librespot[2663]: time="2025-09-09T16:57:21+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:21 volumioho go-librespot[2663]: time="2025-09-09T16:57:21+02:00" level=debug msg="app state loaded" Sep 09 16:57:21 volumioho go-librespot[2663]: time="2025-09-09T16:57:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:22 volumioho go-librespot[2663]: time="2025-09-09T16:57: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 192.168.211.1:443: connect: connection refused" Sep 09 16:57:22 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:22 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:22 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:22 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:22 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:23 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:23 volumioho volumio[976]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 16:57:24 volumioho volumio[976]: info: CALLMETHOD: system_controller network saveWiredNet [object Object] Sep 09 16:57:24 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , saveWiredNet Sep 09 16:57:24 volumioho sudo[2677]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/network/interfaces Sep 09 16:57:24 volumioho sudo[2677]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:24 volumioho sudo[2677]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:24 volumioho sudo[2679]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/dhcpcd.conf Sep 09 16:57:24 volumioho sudo[2679]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:24 volumioho sudo[2679]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:24 volumioho volumio[976]: info: Permissions for /etc/network/interfaces set Sep 09 16:57:24 volumioho volumio[976]: info: Restarting Wired Network Sep 09 16:57:24 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart Sep 09 16:57:24 volumioho volumio[976]: info: Discovery: Restarting Advertising due to device name change Sep 09 16:57:24 volumioho sudo[2682]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/ip addr flush dev eth0 Sep 09 16:57:24 volumioho sudo[2682]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:24 volumioho avahi-daemon[565]: Withdrawing address record for 192.168.0.107 on eth0. Sep 09 16:57:24 volumioho avahi-daemon[565]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.0.107. Sep 09 16:57:24 volumioho avahi-daemon[565]: Interface eth0.IPv4 no longer relevant for mDNS. Sep 09 16:57:24 volumioho sudo[2682]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:24 volumioho dhcpcd[659]: eth0: pid 2683 deleted IP address 192.168.0.107/24 Sep 09 16:57:24 volumioho dhcpcd[659]: eth0: deleting route to 192.168.0.0/24 Sep 09 16:57:24 volumioho volumio[976]: info: Discovery: A device disappeared from network Sep 09 16:57:24 volumioho volumio[976]: info: Discovery: Device volumioho disappeared from network Sep 09 16:57:24 volumioho sudo[2685]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 down Sep 09 16:57:24 volumioho sudo[2685]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:24 volumioho dnsmasq[966]: reading /etc/resolv.conf Sep 09 16:57:24 volumioho dnsmasq[966]: using nameserver 208.67.222.222#53 Sep 09 16:57:24 volumioho dnsmasq[966]: using nameserver 208.67.220.220#53 Sep 09 16:57:24 volumioho kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Sep 09 16:57:24 volumioho kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Sep 09 16:57:24 volumioho sudo[2685]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:24 volumioho dhcpcd[659]: eth0: probing address 192.168.0.107/24 Sep 09 16:57:24 volumioho dhcpcd[659]: arp_probe1: Network is down Sep 09 16:57:24 volumioho dhcpcd[659]: arp_read: eth0: Network is down Sep 09 16:57:24 volumioho sudo[2697]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 up Sep 09 16:57:24 volumioho sudo[2697]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:24 volumioho sudo[2697]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:24 volumioho kernel: smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup Sep 09 16:57:24 volumioho kernel: smsc95xx 1-1.1:1.0 eth0: Link is Down Sep 09 16:57:24 volumioho dhcpcd[659]: eth0: carrier lost Sep 09 16:57:24 volumioho ifplugd(eth0)[862]: Link beat lost. Sep 09 16:57:25 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:25 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Sep 09 16:57:25 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:25 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:25 volumioho go-librespot[2721]: go-librespot daemon starting... Sep 09 16:57:25 volumioho go-librespot[2721]: time="2025-09-09T16:57:25+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:25 volumioho go-librespot[2721]: time="2025-09-09T16:57:25+02:00" level=debug msg="app state loaded" Sep 09 16:57:25 volumioho go-librespot[2721]: time="2025-09-09T16:57:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:57:25 volumioho volumio[976]: info: Discovery: A device disappeared from network Sep 09 16:57:25 volumioho dhcpcd[659]: eth0: carrier acquired Sep 09 16:57:25 volumioho dhcpcd[659]: eth0: confile file changed, expiring leases Sep 09 16:57:25 volumioho kernel: smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off Sep 09 16:57:25 volumioho dhcpcd[659]: eth0: IAID eb:ee:de:4d Sep 09 16:57:26 volumioho dhcpcd[659]: eth0: soliciting an IPv6 router Sep 09 16:57:26 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:57:26 volumioho go-librespot[2721]: time="2025-09-09T16:57:26+02:00" level=debug msg="new websocket client" Sep 09 16:57:26 volumioho volumio[976]: info: Connection to go-librespot Websocket established Sep 09 16:57:26 volumioho dhcpcd[659]: eth0: rebinding lease of 192.168.0.107 Sep 09 16:57:26 volumioho ifplugd(eth0)[862]: Link beat detected. Sep 09 16:57:27 volumioho ntpd[855]: Deleting interface #3 eth0, 192.168.0.107#123, interface stats: received=0, sent=0, dropped=0, active_time=238 secs Sep 09 16:57:27 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:57:28 volumioho volumio[976]: info: Volumio Network Manager: Network status updated: 0 Sep 09 16:57:29 volumioho volumio[976]: info: Discovery: Started advertising with name: VolumioHO Sep 09 16:57:29 volumioho volumio[976]: info: Getting Spotify volume Sep 09 16:57:29 volumioho volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 09 16:57:29 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:29 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:29 volumioho volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 11 Sep 09 16:57:29 volumioho volumio[976]: SPOTIFY: SPOTIFY VOLUME undefined Sep 09 16:57:29 volumioho volumio[976]: SPOTIFY: VOLUMIO VOLUME 11 Sep 09 16:57:29 volumioho volumio[976]: info: Aligning Spotify Volume to Volumio Volume Sep 09 16:57:29 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:29 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:29 volumioho volumio[976]: info: Setting Spotify Volume from Volumio: 11 Sep 09 16:57:30 volumioho dhcpcd[659]: eth0: NAK: address in use from 192.168.0.1 Sep 09 16:57:30 volumioho dhcpcd[659]: eth0: message: address in use Sep 09 16:57:30 volumioho dhcpcd[659]: eth0: soliciting a DHCP lease Sep 09 16:57:31 volumioho volumio[976]: SPOTIFY: SETTING SPOTIFY VOLUME 11 Sep 09 16:57:31 volumioho volumio[976]: info: Sending Spotify command with payload to local API: /player/volume Sep 09 16:57:33 volumioho dhcpcd[659]: eth0: offered 192.168.0.108 from 192.168.0.1 Sep 09 16:57:33 volumioho dhcpcd[659]: eth0: probing address 192.168.0.108/24 Sep 09 16:57:34 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Sep 09 16:57:34 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Sep 09 16:57:34 volumioho volumio[976]: info: Refreshing Cached IP Addresses Sep 09 16:57:34 volumioho sudo[2765]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Sep 09 16:57:34 volumioho sudo[2765]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:34 volumioho sudo[2765]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:34 volumioho sudo[2767]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 09 16:57:34 volumioho sudo[2767]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:34 volumioho sudo[2767]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:34 volumioho sudo[2770]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 09 16:57:34 volumioho sudo[2770]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:34 volumioho sudo[2770]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:34 volumioho systemd[1]: upmpdcli.service: Succeeded. Sep 09 16:57:38 volumioho dhcpcd[659]: eth0: leased 192.168.0.108 for 604800 seconds Sep 09 16:57:38 volumioho dhcpcd[659]: eth0: adding route to 192.168.0.0/24 Sep 09 16:57:38 volumioho dhcpcd[659]: eth0: adding default route via 192.168.0.1 Sep 09 16:57:38 volumioho dhcpcd[659]: wlan0: deleting default route Sep 09 16:57:38 volumioho avahi-daemon[565]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.108. Sep 09 16:57:38 volumioho avahi-daemon[565]: New relevant interface eth0.IPv4 for mDNS. Sep 09 16:57:38 volumioho avahi-daemon[565]: Registering new address record for 192.168.0.108 on eth0.IPv4. Sep 09 16:57:38 volumioho dnsmasq[966]: reading /etc/resolv.conf Sep 09 16:57:38 volumioho dnsmasq[966]: using nameserver 192.168.0.1#53 Sep 09 16:57:38 volumioho dnsmasq[966]: using nameserver 208.67.222.222#53 Sep 09 16:57:38 volumioho dnsmasq[966]: using nameserver 208.67.220.220#53 Sep 09 16:57:38 volumioho ntpd[855]: ntpd exiting on signal 15 (Terminated) Sep 09 16:57:38 volumioho systemd[1]: Stopping Network Time Service... Sep 09 16:57:38 volumioho systemd[1]: ntp.service: Succeeded. Sep 09 16:57:38 volumioho systemd[1]: Stopped Network Time Service. Sep 09 16:57:38 volumioho systemd[1]: Starting Network Time Service... Sep 09 16:57:38 volumioho ntpd[2818]: ntpd 4.2.8p12@1.3728-o (1): Starting Sep 09 16:57:38 volumioho ntpd[2818]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -c /run/ntp.conf.dhcp -u 103:103 Sep 09 16:57:38 volumioho systemd[1]: Started Network Time Service. Sep 09 16:57:38 volumioho ntpd[2825]: proto: precision = 0.729 usec (-20) Sep 09 16:57:38 volumioho ntpd[2825]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Sep 09 16:57:38 volumioho ntpd[2825]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Sep 09 16:57:38 volumioho ntpd[2825]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 256 days ago Sep 09 16:57:38 volumioho ntpd[2825]: Listen and drop on 0 v6wildcard [::]:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listen normally on 2 lo 127.0.0.1:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listen normally on 3 eth0 192.168.0.108:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listen normally on 4 wlan0 192.168.211.1:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listen normally on 5 wlan0 169.254.38.167:123 Sep 09 16:57:38 volumioho ntpd[2825]: Listening on routing socket on fd #22 for interface updates Sep 09 16:57:38 volumioho ntpd[2825]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Sep 09 16:57:38 volumioho ntpd[2825]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Sep 09 16:57:39 volumioho ntpd[2825]: Soliciting pool server 213.172.105.106 Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 09 16:57:40 volumioho volumio[976]: info: Discovery: Getting this device information Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:40 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 09 16:57:40 volumioho volumio[976]: verbose: New Socket.io Connection to 192.168.0.108:3000 from 192.168.0.234 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:40 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 09 16:57:40 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 09 16:57:40 volumioho ntpd[2825]: Soliciting pool server 94.130.184.193 Sep 09 16:57:40 volumioho ntpd[2825]: Soliciting pool server 213.239.234.28 Sep 09 16:57:41 volumioho ntpd[2825]: Soliciting pool server 80.153.195.191 Sep 09 16:57:41 volumioho ntpd[2825]: Soliciting pool server 5.189.151.39 Sep 09 16:57:41 volumioho ntpd[2825]: Soliciting pool server 152.70.19.169 Sep 09 16:57:42 volumioho ntpd[2825]: Soliciting pool server 167.235.70.245 Sep 09 16:57:42 volumioho ntpd[2825]: Soliciting pool server 78.47.56.71 Sep 09 16:57:42 volumioho ntpd[2825]: Soliciting pool server 78.47.93.191 Sep 09 16:57:42 volumioho ntpd[2825]: Soliciting pool server 195.201.173.232 Sep 09 16:57:43 volumioho ntpd[2825]: Soliciting pool server 178.63.9.212 Sep 09 16:57:43 volumioho ntpd[2825]: Soliciting pool server 49.12.35.6 Sep 09 16:57:43 volumioho ntpd[2825]: Soliciting pool server 49.13.223.236 Sep 09 16:57:44 volumioho volumio[976]: info: Discovery: adding 59724dd9-1e5a-4c3f-b008-38443f5c8997 Sep 09 16:57:44 volumioho volumio[976]: info: Discovery: Found device VolumioHO Sep 09 16:57:44 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:44 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:44 volumioho sudo[2828]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 09 16:57:44 volumioho sudo[2828]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:44 volumioho volumio[976]: info: Discovery: this is already registered, 59724dd9-1e5a-4c3f-b008-38443f5c8997 Sep 09 16:57:44 volumioho volumio[976]: info: Discovery: Found device VolumioHO Sep 09 16:57:44 volumioho volumio[976]: info: CoreCommandRouter::volumioGetState Sep 09 16:57:44 volumioho volumio[976]: info: CorePlayQueue::getTrack 0 Sep 09 16:57:44 volumioho sudo[2828]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:44 volumioho sudo[2830]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 09 16:57:44 volumioho sudo[2830]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:44 volumioho sudo[2830]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:44 volumioho sudo[2834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 09 16:57:44 volumioho sudo[2834]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:57:44 volumioho systemd[1]: Started UPnP Renderer front-end to MPD. Sep 09 16:57:44 volumioho sudo[2834]: pam_unix(sudo:session): session closed for user root Sep 09 16:57:44 volumioho volumio[976]: info: Upmpdcli Daemon Started Sep 09 16:57:44 volumioho volumio[2836]: writing RSA key Sep 09 16:57:44 volumioho ntpd[2825]: Soliciting pool server 49.13.14.46 Sep 09 16:57:44 volumioho ntpd[2825]: Soliciting pool server 81.169.217.236 Sep 09 16:57:45 volumioho go-librespot[2721]: time="2025-09-09T16:57:45+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" Sep 09 16:57:45 volumioho systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 16:57:45 volumioho systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 16:57:45 volumioho volumio[976]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Sep 09 16:57:45 volumioho volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 09 16:57:45 volumioho volumio[976]: at connResetException (internal/errors.js:607:14) Sep 09 16:57:45 volumioho volumio[976]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 09 16:57:45 volumioho volumio[976]: at Socket.emit (events.js:327:22) Sep 09 16:57:45 volumioho volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 09 16:57:45 volumioho volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 09 16:57:45 volumioho volumio[976]: (Use `node --trace-warnings ...` to show where the warning was created) Sep 09 16:57:45 volumioho volumio[976]: (node:976) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 26) Sep 09 16:57:45 volumioho volumio[976]: (node:976) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Sep 09 16:57:45 volumioho volumio[976]: info: Connection to go-librespot Websocket closed Sep 09 16:57:45 volumioho ntpd[2825]: Soliciting pool server 78.47.168.188 Sep 09 16:57:45 volumioho ntpd[2825]: Soliciting pool server 2a02:a00:1009:6202::123 Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin bluetooth to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin multiroom to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin metavolumio to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin cd_controller to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 09 16:57:46 volumioho volumio[976]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 09 16:57:47 volumioho volumio-time-update[573]: volumio-time-update-util: Date not found in response Sep 09 16:57:47 volumioho volumio-time-update[573]: volumio-time-update-util: Retrying in 5 seconds... Sep 09 16:57:48 volumioho volumio[976]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 09 16:57:48 volumioho volumio[976]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 09 16:57:48 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 09 16:57:48 volumioho volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 09 16:57:48 volumioho volumio[976]: info: Starting MyVolumio Remote Streaming Endpoints Sep 09 16:57:48 volumioho volumio[976]: info: MyVolumio login type: Token Sep 09 16:57:48 volumioho volumio[976]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 09 16:57:48 volumioho volumio[976]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 09 16:57:48 volumioho systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 16:57:48 volumioho systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Sep 09 16:57:48 volumioho systemd[1]: Stopped go-librespot Daemon. Sep 09 16:57:48 volumioho systemd[1]: Started go-librespot Daemon. Sep 09 16:57:48 volumioho go-librespot[2872]: go-librespot daemon starting... Sep 09 16:57:48 volumioho go-librespot[2872]: time="2025-09-09T16:57:48+02:00" level=info msg="running go-librespot 0.3.2" Sep 09 16:57:48 volumioho go-librespot[2872]: time="2025-09-09T16:57:48+02:00" level=debug msg="app state loaded" Sep 09 16:57:48 volumioho go-librespot[2872]: time="2025-09-09T16:57:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 09 16:58:12 volumioho ntpd[2825]: receive: Unexpected origin timestamp 0xec6abeec.db79d0b2 does not match aorg 0000000000.00000000 from server@80.153.195.191 xmt 0xec6abf04.048709e2 Sep 09 16:58:12 volumioho ntpd[2825]: receive: Unexpected origin timestamp 0xec6abeec.db781e6d does not match aorg 0000000000.00000000 from server@152.70.19.169 xmt 0xec6abf04.09e36a56 Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+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]" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+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]" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+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]" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=info msg="zeroconf server listening on port 42771" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="obtained new client token: AACvjnZ4SQDAWIEa5nXYW2uPfNmLCll2gWCXxx04mJhXywrzN4+C+7RDOPca4X8ibvQIs6BLlKyx/NmUKuNCseQurRYlxmF5w+P36w3/LEyV8j9XaSj5a4AwutsrUs9oEm/gAVtjxu6uDtFtaGio57zVkqw0Lgo4FxcUkr++bddB1zt8imPwDLO0CI4Q685ve0vanGWFegWp2QuMKzvOVlZd3Ph+uRWdJDnQt6tdMwXwbZusyHZNtcZf" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="completed keyexchange" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="completed challenge" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=info msg="authenticated AP" username="31************************24" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=info msg="authenticated Login5" username="31************************24" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="initializing zeroconf session" username="31************************24" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="dealer connection opened" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=trace msg="starting accesspoint recv loop" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=trace msg="starting dealer recv loop" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=trace msg="received accesspoint ping" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=debug msg="received connection id: Mjg3MTk4OWItN2Rj...RjMwMjMwMTU5Ng==" Sep 09 16:58:12 volumioho volumio[976]: info: Starting Streaming Service Transparent Proxy Sep 09 16:58:12 volumioho go-librespot[2872]: time="2025-09-09T16:58:12+02:00" level=trace msg="received accesspoint pong ack" Sep 09 16:58:12 volumioho volumio[976]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 09 16:58:12 volumioho volumio[976]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 09 16:58:12 volumioho volumio[976]: info: Streaming services startup Sep 09 16:58:12 volumioho volumio[976]: info: Starting Streaming Daemon Sep 09 16:58:12 volumioho sudo[2902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 09 16:58:12 volumioho sudo[2902]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:58:12 volumioho sudo[2902]: pam_unix(sudo:session): session closed for user root Sep 09 16:58:13 volumioho volumio[976]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 09 16:58:13 volumioho go-librespot[2872]: time="2025-09-09T16:58:13+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 09 16:58:13 volumioho volumio[976]: info: Initializing connection to go-librespot Websocket Sep 09 16:58:13 volumioho volumio[976]: info: Volumio Network Manager: Network status updated: 1 Sep 09 16:58:13 volumioho volumio[976]: error: Cannot start Volumio Streaming Daemon Sep 09 16:58:13 volumioho volumio[976]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 09 16:58:13 volumioho volumio[976]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 09 16:58:13 volumioho go-librespot[2872]: time="2025-09-09T16:58:13+02:00" level=debug msg="new websocket client" Sep 09 16:58:13 volumioho volumio[976]: info: Connection to go-librespot Websocket established Sep 09 16:58:13 volumioho volumio[976]: error: MyVolumio Custom Token format not valid, refreshing it Sep 09 16:58:14 volumioho volumio[976]: STREAMING PROXY: Starting server on port 3245 Sep 09 16:58:14 volumioho volumio[976]: Node JS runtime: 14 Sep 09 16:58:14 volumioho volumio[976]: info: MyVolumio login type: Token Sep 09 16:58:15 volumioho volumio[976]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Sep 09 16:58:15 volumioho volumio-time-update[573]: volumio-time-update-util: Fetching time from Volumio... Sep 09 16:58:15 volumioho volumio[976]: info: MyVolumio token set successfully Sep 09 16:58:15 volumioho volumio[976]: info: MYVOLUMIO: Adding device Sep 09 16:58:15 volumioho volumio[976]: info: MYVOLUMIO: Evaluating Server Sep 09 16:58:15 volumioho volumio-time-update[573]: volumio-time-update-util: Setting system time to: 2025-09-09 16:58:15 Sep 09 16:58:15 volumioho sudo[2917]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-09-09 16:58:15 Sep 09 16:58:15 volumioho sudo[2917]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:58:15 volumioho dbus-daemon[571]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.19' (uid=0 pid=2918 comm="timedatectl set-time 2025-09-09 16:58:15 ") Sep 09 16:58:15 volumioho systemd[1]: Starting Time & Date Service... Sep 09 16:58:16 volumioho dbus-daemon[571]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 09 16:58:16 volumioho systemd[1]: Started Time & Date Service. Sep 09 16:58:15 volumioho systemd-timedated[2919]: Changed local time to Tue Sep 9 16:58:15 2025 Sep 09 16:58:15 volumioho sudo[2917]: pam_unix(sudo:session): session closed for user root Sep 09 16:58:15 volumioho volumio-time-update[573]: volumio-time-update-util: System time updated successfully. Sep 09 16:58:15 volumioho systemd[1]: Started Volumio Time Update Utility. Sep 09 16:58:15 volumioho systemd[1]: Reached target Multi-User System. Sep 09 16:58:15 volumioho systemd[1]: Reached target Graphical Interface. Sep 09 16:58:15 volumioho volumio[976]: info: Getting Spotify volume Sep 09 16:58:15 volumioho systemd[1]: Starting Update UTMP about System Runlevel Changes... Sep 09 16:58:15 volumioho volumio[976]: info: MyVolumio status changed Sep 09 16:58:15 volumioho volumio[976]: info: Streaming services startup Sep 09 16:58:15 volumioho volumio[976]: info: Starting Streaming Daemon Sep 09 16:58:15 volumioho volumio[976]: info: Removing browser output: myVolumio user plan is not superstar Sep 09 16:58:15 volumioho volumio[976]: info: Removing audio output: Sep 09 16:58:15 volumioho volumio[976]: info: Stoppping Tunnel 1 Sep 09 16:58:15 volumioho sudo[2938]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 09 16:58:15 volumioho sudo[2938]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:58:15 volumioho systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Sep 09 16:58:15 volumioho systemd[1]: Started Update UTMP about System Runlevel Changes. Sep 09 16:58:15 volumioho systemd[1]: Startup finished in 14.059s (kernel) + 4min 38.592s (userspace) = 4min 52.651s. Sep 09 16:58:15 volumioho sudo[2940]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Sep 09 16:58:15 volumioho sudo[2940]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 09 16:58:15 volumioho volumio[976]: error: Failed to ping endpoint us1.myvolumio.org : unknown error Sep 09 16:58:15 volumioho sudo[2938]: pam_unix(sudo:session): session closed for user root Sep 09 16:58:15 volumioho volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 09 16:58:15 volumioho volumio[976]: Error: Unable to resolve or reject the same promise twice Sep 09 16:58:15 volumioho volumio[976]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Sep 09 16:58:15 volumioho volumio[976]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32086) Sep 09 16:58:15 volumioho volumio[976]: at Socket.emit (events.js:327:22) Sep 09 16:58:15 volumioho volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 09 16:58:15 volumioho volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 09 16:58:15 volumioho sudo[2940]: pam_unix(sudo:session): session closed for user root Sep 09 16:58:15 volumioho volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 09 16:58:15 volumioho sudo[2952]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-09 16:57 Sep 09 16:58:15 volumioho sudo[2952]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"