-- Logs begin at Sun 2024-11-24 11:29:51 CET, end at Sun 2024-11-24 11:35:31 CET. -- Nov 24 11:34:05 euterpe ntpd[3062]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Nov 24 11:34:06 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 24 11:34:07 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 24 11:34:16 euterpe volumio-time-update[2815]: volumio-time-update-util: Date not found in response Nov 24 11:34:16 euterpe volumio-time-update[2815]: volumio-time-update-util: Retrying in 5 seconds... Nov 24 11:34:18 euterpe go-librespot[4935]: time="2024-11-24T11:34:18+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Nov 24 11:34:18 euterpe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 24 11:34:18 euterpe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 24 11:34:21 euterpe volumio-time-update[2815]: volumio-time-update-util: Fetching time from Volumio... Nov 24 11:34:21 euterpe systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 24 11:34:21 euterpe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Nov 24 11:34:21 euterpe systemd[1]: Stopped go-librespot Daemon. Nov 24 11:34:21 euterpe systemd[1]: Started go-librespot Daemon. Nov 24 11:34:21 euterpe go-librespot[4988]: Librespot-go daemon starting... Nov 24 11:34:21 euterpe go-librespot[4988]: time="2024-11-24T11:34:21+01:00" level=info msg="generated new device id: 528c1af7bc7294093fb0cfcde27b36d6f3ebc992" Nov 24 11:34:21 euterpe go-librespot[4988]: time="2024-11-24T11:34:21+01:00" level=debug msg="stored credentials found for t0la82pl9f7j9yx4d2de2z0nj" Nov 24 11:34:25 euterpe ntpd[3062]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Nov 24 11:34:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 24 11:34:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 24 11:34:41 euterpe volumio-time-update[2815]: volumio-time-update-util: Date not found in response Nov 24 11:34:41 euterpe volumio-time-update[2815]: volumio-time-update-util: Retrying in 5 seconds... Nov 24 11:34:41 euterpe go-librespot[4988]: time="2024-11-24T11:34:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Nov 24 11:34:41 euterpe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 24 11:34:41 euterpe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 24 11:34:44 euterpe systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 24 11:34:44 euterpe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Nov 24 11:34:44 euterpe systemd[1]: Stopped go-librespot Daemon. Nov 24 11:34:44 euterpe systemd[1]: Started go-librespot Daemon. Nov 24 11:34:44 euterpe go-librespot[5046]: Librespot-go daemon starting... Nov 24 11:34:44 euterpe go-librespot[5046]: time="2024-11-24T11:34:44+01:00" level=info msg="generated new device id: 62cb0f8be715050980794bd1403af0487d617b7c" Nov 24 11:34:44 euterpe go-librespot[5046]: time="2024-11-24T11:34:44+01:00" level=debug msg="stored credentials found for t0la82pl9f7j9yx4d2de2z0nj" Nov 24 11:34:45 euterpe ntpd[3062]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Nov 24 11:34:46 euterpe volumio-time-update[2815]: volumio-time-update-util: Fetching time from Volumio... Nov 24 11:34:46 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 24 11:34:47 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 24 11:35:05 euterpe go-librespot[5046]: time="2024-11-24T11:35:05+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Nov 24 11:35:05 euterpe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 24 11:35:05 euterpe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 24 11:35:05 euterpe ntpd[3062]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Nov 24 11:35:06 euterpe volumio-time-update[2815]: volumio-time-update-util: Date not found in response Nov 24 11:35:06 euterpe volumio-time-update[2815]: volumio-time-update-util: Retrying in 5 seconds... Nov 24 11:35:07 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 24 11:35:08 euterpe systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 24 11:35:08 euterpe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Nov 24 11:35:08 euterpe systemd[1]: Stopped go-librespot Daemon. Nov 24 11:35:08 euterpe systemd[1]: Started go-librespot Daemon. Nov 24 11:35:08 euterpe go-librespot[5177]: Librespot-go daemon starting... Nov 24 11:35:08 euterpe go-librespot[5177]: time="2024-11-24T11:35:08+01:00" level=info msg="generated new device id: b325061ee50e0f7c7ddea3244507c3ff28a06b9a" Nov 24 11:35:08 euterpe go-librespot[5177]: time="2024-11-24T11:35:08+01:00" level=debug msg="stored credentials found for t0la82pl9f7j9yx4d2de2z0nj" Nov 24 11:35:11 euterpe volumio-time-update[2815]: volumio-time-update-util: Fetching time from Volumio... Nov 24 11:35:19 euterpe dhcpcd[3489]: eth0: offered 192.168.178.26 from 192.168.178.1 Nov 24 11:35:19 euterpe dhcpcd[3489]: eth0: probing address 192.168.178.26/24 Nov 24 11:35:21 euterpe dhcpcd[3447]: eth0: offered 192.168.178.26 from 192.168.178.1 Nov 24 11:35:21 euterpe dhcpcd[3447]: eth0: probing address 192.168.178.26/24 Nov 24 11:35:24 euterpe dhcpcd[3489]: eth0: leased 192.168.178.26 for 864000 seconds Nov 24 11:35:24 euterpe dhcpcd[3489]: eth0: adding route to 192.168.178.0/24 Nov 24 11:35:24 euterpe dhcpcd[3489]: eth0: changing default route via 192.168.178.1 Nov 24 11:35:24 euterpe avahi-daemon[2845]: Registering new address record for 192.168.178.26 on eth0.IPv4. Nov 24 11:35:24 euterpe dhcpcd[3447]: eth0: deleted default route Nov 24 11:35:25 euterpe ntpd[3062]: ntpd exiting on signal 15 (Terminated) Nov 24 11:35:25 euterpe systemd[1]: Stopping Network Time Service... Nov 24 11:35:25 euterpe systemd[1]: ntp.service: Succeeded. Nov 24 11:35:25 euterpe systemd[1]: Stopped Network Time Service. Nov 24 11:35:25 euterpe systemd[1]: Starting Network Time Service... Nov 24 11:35:25 euterpe ntpd[5247]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 24 11:35:25 euterpe ntpd[5247]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -c /run/ntp.conf.dhcp -u 104:103 Nov 24 11:35:25 euterpe systemd[1]: Started Network Time Service. Nov 24 11:35:25 euterpe ntpd[5266]: proto: precision = 1.250 usec (-20) Nov 24 11:35:25 euterpe ntpd[5266]: Listen and drop on 0 v6wildcard [::]:123 Nov 24 11:35:25 euterpe ntpd[5266]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 24 11:35:25 euterpe avahi-daemon[2845]: Withdrawing address record for 169.254.243.220 on eth0. Nov 24 11:35:25 euterpe avahi-daemon[2845]: Leaving mDNS multicast group on interface eth0.IPv4 with address 169.254.243.220. Nov 24 11:35:25 euterpe avahi-daemon[2845]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.178.26. Nov 24 11:35:25 euterpe dhcpcd[3489]: eth0: deleting route to 169.254.0.0/16 Nov 24 11:35:25 euterpe ntpd[5266]: Listen normally on 2 lo 127.0.0.1:123 Nov 24 11:35:25 euterpe ntpd[5266]: Listen normally on 3 eth0 192.168.178.26:123 Nov 24 11:35:25 euterpe ntpd[5266]: Listening on routing socket on fd #20 for interface updates Nov 24 11:35:25 euterpe ntpd[5266]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 24 11:35:25 euterpe ntpd[5266]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 24 11:35:26 euterpe volumio-time-update[2815]: volumio-time-update-util: Date not found in response Nov 24 11:35:26 euterpe volumio-time-update[2815]: volumio-time-update-util: Retrying in 5 seconds... Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 24 11:35:26 euterpe dhcpcd[3447]: eth0: leased 192.168.178.26 for 864000 seconds Nov 24 11:35:26 euterpe dhcpcd[3447]: eth0: adding route to 192.168.178.0/24 Nov 24 11:35:26 euterpe dhcpcd[3447]: eth0: adding default route via 192.168.178.1 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 24 11:35:26 euterpe go-librespot[5177]: time="2024-11-24T11:35:26+01:00" level=debug msg="new websocket client" Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 24 11:35:26 euterpe volumio[3118]: info: Connection to go-librespot Websocket established Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Nov 24 11:35:26 euterpe ntpd[5266]: ntpd exiting on signal 15 (Terminated) Nov 24 11:35:26 euterpe ntpd[5266]: 192.168.178.1 local addr 192.168.178.26 -> Nov 24 11:35:26 euterpe systemd[1]: Stopping Network Time Service... Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Nov 24 11:35:26 euterpe systemd[1]: ntp.service: Succeeded. Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 16 Nov 24 11:35:26 euterpe systemd[1]: Stopped Network Time Service. Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 17 Nov 24 11:35:26 euterpe systemd[1]: Starting Network Time Service... Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 18 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 20 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 21 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 22 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 23 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 24 Nov 24 11:35:26 euterpe ntpd[5327]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 24 11:35:26 euterpe ntpd[5327]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -c /run/ntp.conf.dhcp -u 104:103 Nov 24 11:35:26 euterpe systemd[1]: Started Network Time Service. Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 25 Nov 24 11:35:26 euterpe dhcpcd[3447]: eth0: deleting route to 169.254.0.0/16 Nov 24 11:35:26 euterpe ntpd[5333]: proto: precision = 1.291 usec (-19) Nov 24 11:35:26 euterpe ntpd[5333]: Listen and drop on 0 v6wildcard [::]:123 Nov 24 11:35:26 euterpe ntpd[5333]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 24 11:35:26 euterpe ntpd[5333]: Listen normally on 2 lo 127.0.0.1:123 Nov 24 11:35:26 euterpe ntpd[5333]: Listen normally on 3 eth0 192.168.178.26:123 Nov 24 11:35:26 euterpe ntpd[5333]: Listening on routing socket on fd #20 for interface updates Nov 24 11:35:26 euterpe ntpd[5333]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 24 11:35:26 euterpe ntpd[5333]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 26 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 27 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 28 Nov 24 11:35:26 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 29 Nov 24 11:35:27 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 30 Nov 24 11:35:27 euterpe volumio[3118]: info: CoreCommandRouter::volumioGetState Nov 24 11:35:27 euterpe volumio[3118]: info: Signalling Playback active due to playback status change Nov 24 11:35:27 euterpe volumio[3118]: info: MCU Signalled Playback Active Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 24 11:35:27 euterpe volumio[3118]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 24 11:35:28 euterpe go-librespot[5177]: time="2024-11-24T11:35:28+01:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Nov 24 11:35:28 euterpe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 24 11:35:28 euterpe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 24 11:35:28 euterpe volumio[3118]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 24 11:35:28 euterpe volumio[3118]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 24 11:35:28 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 11:35:28 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 11:35:28 euterpe volumio[3118]: info: Starting MyVolumio Remote Streaming Endpoints Nov 24 11:35:29 euterpe volumio[3118]: info: MyVolumio login type: Token Nov 24 11:35:29 euterpe volumio[3118]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 24 11:35:29 euterpe volumio[3118]: 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' Nov 24 11:35:29 euterpe volumio[3118]: info: Connection to go-librespot Websocket closed Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 24 11:35:29 euterpe volumio[3118]: info: Received Get System Info Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 24 11:35:29 euterpe volumio[3118]: info: Discovery: Getting this device information Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::volumioGetState Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 24 11:35:29 euterpe volumio[3118]: error: MyVolumio Custom Token format not valid, refreshing it Nov 24 11:35:29 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 31 Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::volumioGetState Nov 24 11:35:29 euterpe volumio[3118]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Nov 24 11:35:29 euterpe volumio[3118]: SPOTIFY: SPOTIFY VOLUME undefined Nov 24 11:35:29 euterpe volumio[3118]: SPOTIFY: VOLUMIO VOLUME 40 Nov 24 11:35:29 euterpe volumio[3118]: info: Aligning Spotify Volume to Volumio Volume Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::volumioGetState Nov 24 11:35:29 euterpe volumio[3118]: info: Setting Spotify Volume from Volumio: 40 Nov 24 11:35:29 euterpe volumio[3118]: info: Getting Spotify volume Nov 24 11:35:29 euterpe volumio[3118]: (node:3118) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 24 11:35:29 euterpe volumio[3118]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Nov 24 11:35:29 euterpe volumio[3118]: (node:3118) 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: 4) Nov 24 11:35:29 euterpe volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 32 Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::volumioGetState Nov 24 11:35:29 euterpe volumio[3118]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Nov 24 11:35:29 euterpe volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 24 11:35:29 euterpe volumio[3118]: info: MyVolumio login type: Token Nov 24 11:35:30 euterpe volumio[3118]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 24 11:35:30 euterpe volumio[3118]: info: MyVolumio login type: Token Nov 24 11:35:30 euterpe volumio[3118]: info: MyVolumio token set successfully Nov 24 11:35:30 euterpe volumio[3118]: info: MYVOLUMIO: Adding device Nov 24 11:35:30 euterpe volumio[3118]: info: MYVOLUMIO: Evaluating Server Nov 24 11:35:30 euterpe volumio[3118]: SPOTIFY: SETTING SPOTIFY VOLUME 40 Nov 24 11:35:30 euterpe volumio[3118]: info: Sending Spotify command with payload to local API: /player/volume Nov 24 11:35:30 euterpe volumio[3118]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 24 11:35:31 euterpe volumio-time-update[2815]: volumio-time-update-util: Fetching time from Volumio... Nov 24 11:35:31 euterpe volumio-time-update[2815]: volumio-time-update-util: Setting system time to: 2024-11-24 11:35:27 Nov 24 11:35:31 euterpe systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 24 11:35:31 euterpe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Nov 24 11:35:31 euterpe systemd[1]: Stopped go-librespot Daemon. Nov 24 11:35:31 euterpe systemd[1]: Started go-librespot Daemon. Nov 24 11:35:31 euterpe sudo[5385]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2024-11-24 11:35:27 Nov 24 11:35:31 euterpe sudo[5385]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 11:35:31 euterpe go-librespot[5387]: Librespot-go daemon starting... Nov 24 11:35:31 euterpe dbus-daemon[2818]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.20' (uid=0 pid=5388 comm="timedatectl set-time 2024-11-24 11:35:27 " label="kernel") Nov 24 11:35:31 euterpe go-librespot[5387]: time="2024-11-24T11:35:31+01:00" level=info msg="generated new device id: b41f80ccd001d8e87a4eb19daaacfaf8033ea3e7" Nov 24 11:35:31 euterpe go-librespot[5387]: time="2024-11-24T11:35:31+01:00" level=debug msg="stored credentials found for t0la82pl9f7j9yx4d2de2z0nj" Nov 24 11:35:31 euterpe systemd[1]: Starting Time & Date Service... Nov 24 11:35:31 euterpe volumio[3118]: info: MyVolumio status changed Nov 24 11:35:31 euterpe volumio[3118]: info: Streaming services startup Nov 24 11:35:31 euterpe volumio[3118]: info: Starting Streaming Daemon Nov 24 11:35:31 euterpe dbus-daemon[2818]: [system] Successfully activated service 'org.freedesktop.timedate1' Nov 24 11:35:31 euterpe systemd[1]: Started Time & Date Service. Nov 24 11:35:27 euterpe volumio[3118]: info: Removing browser output: myVolumio user plan is not superstar Nov 24 11:35:27 euterpe volumio[3118]: info: Removing audio output: Nov 24 11:35:27 euterpe volumio[3118]: info: Stoppping Tunnel 1 Nov 24 11:35:27 euterpe systemd-timedated[5398]: Changed local time to Sun Nov 24 11:35:27 2024 Nov 24 11:35:27 euterpe volumio-time-update[2815]: volumio-time-update-util: System time updated successfully. Nov 24 11:35:27 euterpe sudo[5385]: pam_unix(sudo:session): session closed for user root Nov 24 11:35:27 euterpe systemd[1]: Started Volumio Time Update Utility. Nov 24 11:35:27 euterpe systemd[1]: Reached target Multi-User System. Nov 24 11:35:27 euterpe systemd[1]: Reached target Graphical Interface. Nov 24 11:35:27 euterpe sudo[5406]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 24 11:35:27 euterpe systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 24 11:35:27 euterpe sudo[5406]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 11:35:27 euterpe sudo[5406]: pam_unix(sudo:session): session closed for user root Nov 24 11:35:27 euterpe sudo[5411]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 24 11:35:27 euterpe sudo[5411]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 11:35:27 euterpe volumio[3118]: error: Failed to ping endpoint as1.myvolumio.org : unknown error Nov 24 11:35:27 euterpe volumio[3118]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 11:35:27 euterpe volumio[3118]: Error: Unable to resolve or reject the same promise twice Nov 24 11:35:27 euterpe volumio[3118]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Nov 24 11:35:27 euterpe volumio[3118]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32086) Nov 24 11:35:27 euterpe volumio[3118]: at Socket.emit (events.js:412:35) Nov 24 11:35:27 euterpe volumio[3118]: at endReadableNT (internal/streams/readable.js:1333:12) Nov 24 11:35:27 euterpe volumio[3118]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Nov 24 11:35:27 euterpe volumio[3118]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 11:35:27 euterpe systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 24 11:35:27 euterpe systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 24 11:35:27 euterpe systemd[1]: Startup finished in 12.794s (kernel) + 5min 40.743s (userspace) = 5min 53.538s. Nov 24 11:35:27 euterpe sudo[5411]: pam_unix(sudo:session): session closed for user root Nov 24 11:35:27 euterpe go-librespot[5387]: time="2024-11-24T11:35:27+01:00" level=debug msg="obtained new client token: AACtAFWlcnqz2bzcr/dt/+g6lau9bJqqmFh5fLtIAp3RC76BpO2AJGpxhEAv0gtgIIswwcPu0gKSkClhbc5qG8oqHyieV16ZetpXeHPa4u0ROU/MxFK0oV9dnP4HqcAOQ/+TnJaLRXQlkFyivGeNLg2qPCAByRXDlzLTp2INMfDNqGo3VtMKuLJW1mpBDMO2UO56sWFayTzAA2WkuKv8NjsoVklxOV3lNx7KJ+MmXU/Cpl+eFCV2fCl0Dw==" Nov 24 11:35:27 euterpe go-librespot[5387]: time="2024-11-24T11:35:27+01: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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 24 11:35:27 euterpe go-librespot[5387]: time="2024-11-24T11:35:27+01:00" level=debug msg="completed keyexchange" Nov 24 11:35:27 euterpe sudo[5424]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-24 11:34 Nov 24 11:35:27 euterpe sudo[5424]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="integro" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 05:23:34 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Integro" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Integro" VOLUMIO_HASH="987a5b043064f53d1447a6f6f94c2b1d"