-- Logs begin at Mon 2024-10-07 19:26:53 CEST, end at Mon 2024-10-07 19:34:28 CEST. -- Oct 07 19:33:02 volumio go-librespot[1648]: time="2024-10-07T19:33:02+02:00" level=debug msg="new websocket client" Oct 07 19:33:02 volumio volumio[964]: info: Connection to go-librespot Websocket established Oct 07 19:33:05 volumio volumio[964]: info: Getting Spotify volume Oct 07 19:33:13 volumio go-librespot[1648]: time="2024-10-07T19:33:13+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" Oct 07 19:33:14 volumio volumio[964]: (node:964) UnhandledPromiseRejectionWarning: Error: socket hang up Oct 07 19:33:14 volumio volumio[964]: at connResetException (internal/errors.js:639:14) Oct 07 19:33:14 volumio volumio[964]: at Socket.socketOnEnd (_http_client.js:499:23) Oct 07 19:33:14 volumio volumio[964]: at Socket.emit (events.js:412:35) Oct 07 19:33:14 volumio volumio[964]: at endReadableNT (internal/streams/readable.js:1333:12) Oct 07 19:33:14 volumio volumio[964]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Oct 07 19:33:14 volumio volumio[964]: (node:964) 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) Oct 07 19:33:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 07 19:33:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 07 19:33:14 volumio volumio[964]: info: Connection to go-librespot Websocket closed Oct 07 19:33:17 volumio volumio[964]: info: Initializing connection to go-librespot Websocket Oct 07 19:33:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 07 19:33:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 07 19:33:17 volumio systemd[1]: Stopped go-librespot Daemon. Oct 07 19:33:17 volumio systemd[1]: Started go-librespot Daemon. Oct 07 19:33:17 volumio go-librespot[1699]: Librespot-go daemon starting... Oct 07 19:33:17 volumio go-librespot[1699]: time="2024-10-07T19:33:17+02:00" level=info msg="generated new device id: 9863ffa0e53e644e5f983ddf359673a7d4e86048" Oct 07 19:33:17 volumio go-librespot[1699]: time="2024-10-07T19:33:17+02:00" level=debug msg="stored credentials found for 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:33:21 volumio ntpd[845]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Oct 07 19:33:29 volumio kernel: usb 2-3: USB disconnect, device number 3 Oct 07 19:33:30 volumio volumio[964]: info: Oct 07 19:33:30 volumio volumio[964]: ---------------------------- USB Audio Device Detached Oct 07 19:33:30 volumio volumio[964]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , usbAudioDetach Oct 07 19:33:30 volumio volumio[964]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 07 19:33:30 volumio volumio[964]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Oct 07 19:33:45 volumio go-librespot[1699]: time="2024-10-07T19:33: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" Oct 07 19:33:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 07 19:33:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 07 19:33:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 07 19:33:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 07 19:33:48 volumio systemd[1]: Stopped go-librespot Daemon. Oct 07 19:33:48 volumio systemd[1]: Started go-librespot Daemon. Oct 07 19:33:48 volumio go-librespot[1716]: Librespot-go daemon starting... Oct 07 19:33:48 volumio go-librespot[1716]: time="2024-10-07T19:33:48+02:00" level=info msg="generated new device id: aed1ca1615fcbf34768f9a46e43b3f7eb1bc9571" Oct 07 19:33:48 volumio go-librespot[1716]: time="2024-10-07T19:33:48+02:00" level=debug msg="stored credentials found for 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:33:49 volumio ntpd[845]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Oct 07 19:34:13 volumio dhcpcd[747]: eth0: carrier acquired Oct 07 19:34:13 volumio kernel: jme 0000:02:00.5 eth0: Link is up at ANed: 100 Mbps, Full-Duplex, MDI Oct 07 19:34:13 volumio dhcpcd[747]: eth0: IAID 49:6f:7d:2e Oct 07 19:34:13 volumio dhcpcd[747]: eth0: adding address fe80::5642:49ff:fe6f:7d2e Oct 07 19:34:13 volumio dhcpcd[747]: ipv6_addaddr1: Permission denied Oct 07 19:34:13 volumio ifplugd(eth0)[843]: Link beat detected. Oct 07 19:34:14 volumio ifplugd(eth0)[843]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Oct 07 19:34:14 volumio dhcpcd[747]: eth0: soliciting an IPv6 router Oct 07 19:34:14 volumio dhcpcd[1787]: sending commands to master dhcpcd process Oct 07 19:34:14 volumio ifplugd(eth0)[843]: client: sending commands to master dhcpcd process Oct 07 19:34:14 volumio dhcpcd[747]: control command: /sbin/dhcpcd eth0 Oct 07 19:34:14 volumio dhcpcd[747]: eth0: soliciting a DHCP lease Oct 07 19:34:14 volumio ifplugd(eth0)[843]: Program executed successfully. Oct 07 19:34:14 volumio dhcpcd[747]: eth0: offered 192.168.0.28 from 192.168.0.1 Oct 07 19:34:15 volumio dhcpcd[747]: eth0: probing address 192.168.0.28/24 Oct 07 19:34:16 volumio go-librespot[1716]: time="2024-10-07T19:34:16+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" Oct 07 19:34:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 07 19:34:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 07 19:34:17 volumio ntpd[845]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Oct 07 19:34:18 volumio kernel: usb 2-1: USB disconnect, device number 2 Oct 07 19:34:18 volumio kernel: wlan0: deauthenticating from 5c:ea:1d:c7:d4:bb by local choice (Reason: 3=DEAUTH_LEAVING) Oct 07 19:34:18 volumio wpa_supplicant[898]: wlan0: CTRL-EVENT-DISCONNECTED bssid=5c:ea:1d:c7:d4:bb reason=3 locally_generated=1 Oct 07 19:34:18 volumio avahi-daemon[685]: Interface wlan0.IPv4 no longer relevant for mDNS. Oct 07 19:34:18 volumio avahi-daemon[685]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.194. Oct 07 19:34:18 volumio dhcpcd[747]: wlan0: carrier lost Oct 07 19:34:18 volumio avahi-daemon[685]: Withdrawing address record for 192.168.1.194 on wlan0. Oct 07 19:34:19 volumio volumio[964]: info: Discovery: A device disappeared from network Oct 07 19:34:19 volumio volumio[964]: info: Discovery: Device volumio disappeared from network Oct 07 19:34:19 volumio systemd[1]: Starting Load/Save RF Kill Switch Status... Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to open /proc/sys/net/ipv4/conf/wlan0/drop_unicast_in_l2_multicast: No such file or directory Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to set IPv4 unicast in multicast filter Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to open /proc/sys/net/ipv4/conf/wlan0/drop_unicast_in_l2_multicast: No such file or directory Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to set IPv4 unicast in multicast filter Oct 07 19:34:19 volumio systemd[1]: Started Load/Save RF Kill Switch Status. Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to open /proc/sys/net/ipv4/conf/wlan0/drop_unicast_in_l2_multicast: No such file or directory Oct 07 19:34:19 volumio wpa_supplicant[898]: nl80211: Failed to set IPv4 unicast in multicast filter Oct 07 19:34:19 volumio dhcpcd[747]: wlan0: deleting route to 192.168.1.0/24 Oct 07 19:34:19 volumio dhcpcd[747]: wlan0: deleting default route via 192.168.1.1 Oct 07 19:34:19 volumio dhcpcd[747]: wlan0: removing interface Oct 07 19:34:19 volumio dhcpcd[747]: eth0: leased 192.168.0.28 for 3600 seconds Oct 07 19:34:19 volumio dhcpcd[747]: eth0: adding route to 192.168.0.0/24 Oct 07 19:34:19 volumio dhcpcd[747]: eth0: adding default route via 192.168.0.1 Oct 07 19:34:19 volumio avahi-daemon[685]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.28. Oct 07 19:34:19 volumio avahi-daemon[685]: New relevant interface eth0.IPv4 for mDNS. Oct 07 19:34:19 volumio avahi-daemon[685]: Registering new address record for 192.168.0.28 on eth0.IPv4. Oct 07 19:34:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 07 19:34:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 07 19:34:19 volumio systemd[1]: Stopped go-librespot Daemon. Oct 07 19:34:19 volumio systemd[1]: Started go-librespot Daemon. Oct 07 19:34:19 volumio go-librespot[1880]: Librespot-go daemon starting... Oct 07 19:34:19 volumio go-librespot[1880]: time="2024-10-07T19:34:19+02:00" level=info msg="generated new device id: 4dd4989e7e344ec9028e81c463bf01ef52a2f6a6" Oct 07 19:34:19 volumio go-librespot[1880]: time="2024-10-07T19:34:19+02:00" level=debug msg="stored credentials found for 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:34:19 volumio ntpd[845]: ntpd exiting on signal 15 (Terminated) Oct 07 19:34:19 volumio systemd[1]: Stopping Network Time Service... Oct 07 19:34:19 volumio systemd[1]: ntp.service: Succeeded. Oct 07 19:34:19 volumio systemd[1]: Stopped Network Time Service. Oct 07 19:34:19 volumio systemd[1]: Starting Network Time Service... Oct 07 19:34:19 volumio ntpd[1903]: ntpd 4.2.8p12@1.3728-o (1): Starting Oct 07 19:34:19 volumio ntpd[1903]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Oct 07 19:34:19 volumio systemd[1]: Started Network Time Service. Oct 07 19:34:19 volumio ntpd[1910]: proto: precision = 1.956 usec (-19) Oct 07 19:34:19 volumio ntpd[1910]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Oct 07 19:34:19 volumio ntpd[1910]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Oct 07 19:34:19 volumio ntpd[1910]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 650 days ago Oct 07 19:34:19 volumio ntpd[1910]: Listen and drop on 0 v6wildcard [::]:123 Oct 07 19:34:19 volumio ntpd[1910]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Oct 07 19:34:19 volumio ntpd[1910]: Listen normally on 2 lo 127.0.0.1:123 Oct 07 19:34:19 volumio ntpd[1910]: Listen normally on 3 eth0 192.168.0.28:123 Oct 07 19:34:19 volumio ntpd[1910]: Listening on routing socket on fd #20 for interface updates Oct 07 19:34:19 volumio ntpd[1910]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 07 19:34:19 volumio ntpd[1910]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02: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]" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02: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]" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02: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]" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02:00" level=debug msg="zeroconf server listening on port 46433" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02:00" level=debug msg="obtained new client token: AADtjl0wCrHrju7lchDzQZMrHubTdWbXciij4yCvEpiJWGqfyQDFRuVp6oroiyNPclgK2F5F8umDt31WW/c72JQTJj5HSjL0nwCPjrz1vjR+DhDyPLwgSjrGE+BES6njms37m7JPqcWQjr1YuAXEL9IJ+yMpMeNgJgM/HD+ii4nLoqUFgCwyhEl+8N8v0MrZY0TLGe5GUTBUYu1LV7bRuqqG6QOu8TQ4GzJJ5MhhECmqf55wLRBiM/hmkiQ=" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02:00" level=debug msg="completed keyexchange" Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02:00" level=debug msg="completed challenge" Oct 07 19:34:20 volumio ntpd[1910]: Soliciting pool server 195.178.58.245 Oct 07 19:34:20 volumio go-librespot[1880]: time="2024-10-07T19:34:20+02:00" level=debug msg="authenticated as 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:34:21 volumio volumio[964]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="new websocket client" Oct 07 19:34:21 volumio volumio[964]: info: Connection to go-librespot Websocket established Oct 07 19:34:21 volumio volumio[964]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 07 19:34:21 volumio volumio[964]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="authenticated as 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:34:21 volumio volumio[964]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 07 19:34:21 volumio volumio[964]: info: CoreCommandRouter::volumioGetState Oct 07 19:34:21 volumio volumio[964]: info: CorePlayQueue::getTrack 0 Oct 07 19:34:21 volumio volumio[964]: info: Discovery: adding 2e88ddff-4a09-42ed-869b-75b82d5ddd84 Oct 07 19:34:21 volumio volumio[964]: info: Discovery: Found device Volumio Oct 07 19:34:21 volumio volumio[964]: info: CoreCommandRouter::volumioGetState Oct 07 19:34:21 volumio volumio[964]: info: CorePlayQueue::getTrack 0 Oct 07 19:34:21 volumio volumio[964]: SPOTIFY: RECEIVED VOLUMIO VOLUME 6 Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="dealer connection opened" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="initializing zeroconf session, username: 31m5gtvgs6jjritmhbrxghepyt6a" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="received connection id: Y2Q4NDFmMGUtYTUxNS00ZWM4LTg0MjItMzgxZDYyNjZkNDdlK2RlYWxlcit0Y3A6Ly8wYWNhNDE3Ni5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNDVFQjhBNDIwM0EyMTRCRkM2QjA0MTgyNjE5MUUyOEE5OEFEQkRDMTZEREM3OUMwMERCNUMyOTQzREM1MDM4OQ==" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 07 19:34:21 volumio go-librespot[1880]: time="2024-10-07T19:34:21+02:00" level=debug msg="autoplay enabled: false" Oct 07 19:34:21 volumio ntpd[1910]: Soliciting pool server 147.91.26.20 Oct 07 19:34:21 volumio ntpd[1910]: Soliciting pool server 195.250.114.105 Oct 07 19:34:21 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 07 19:34:21 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 07 19:34:21 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 07 19:34:21 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 07 19:34:21 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin bluetooth to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin multiroom to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin metavolumio to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin cd_controller to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 07 19:34:22 volumio volumio[964]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 07 19:34:22 volumio ntpd[1910]: Soliciting pool server 217.24.20.5 Oct 07 19:34:22 volumio ntpd[1910]: Soliciting pool server 217.24.20.5 Oct 07 19:34:22 volumio ntpd[1910]: Soliciting pool server 147.91.8.1 Oct 07 19:34:23 volumio volumio[964]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 07 19:34:23 volumio volumio[964]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 07 19:34:23 volumio volumio[964]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 07 19:34:23 volumio volumio[964]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 07 19:34:23 volumio volumio[964]: info: Starting MyVolumio Remote Streaming Endpoints Oct 07 19:34:23 volumio volumio[964]: info: MyVolumio login type: Token Oct 07 19:34:23 volumio volumio[964]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 07 19:34:23 volumio volumio[964]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 07 19:34:23 volumio ntpd[1910]: Soliciting pool server 2a01:7e00::f03c:91ff:fe89:66e3 Oct 07 19:34:24 volumio systemd[1]: systemd-rfkill.service: Succeeded. Oct 07 19:34:25 volumio volumio[964]: info: Starting Streaming Service Transparent Proxy Oct 07 19:34:25 volumio volumio[964]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 07 19:34:25 volumio volumio[964]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 07 19:34:25 volumio volumio[964]: info: Streaming services startup Oct 07 19:34:25 volumio volumio[964]: info: Starting Streaming Daemon Oct 07 19:34:25 volumio sudo[1919]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 07 19:34:25 volumio volumio[964]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 07 19:34:25 volumio sudo[1919]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 07 19:34:25 volumio sudo[1919]: pam_unix(sudo:session): session closed for user root Oct 07 19:34:25 volumio volumio[964]: info: Getting Spotify volume Oct 07 19:34:25 volumio volumio[964]: error: Cannot start Volumio Streaming Daemon Oct 07 19:34:25 volumio volumio[964]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 07 19:34:25 volumio volumio[964]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 07 19:34:26 volumio volumio[964]: info: Spotify volume: 100 Oct 07 19:34:26 volumio volumio[964]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 07 19:34:26 volumio volumio[964]: info: CoreCommandRouter::volumioGetState Oct 07 19:34:26 volumio volumio[964]: info: CorePlayQueue::getTrack 0 Oct 07 19:34:26 volumio volumio[964]: SPOTIFY: RECEIVED VOLUMIO VOLUME 6 Oct 07 19:34:26 volumio volumio[964]: SPOTIFY: SPOTIFY VOLUME 100 Oct 07 19:34:26 volumio volumio[964]: SPOTIFY: VOLUMIO VOLUME 6 Oct 07 19:34:26 volumio volumio[964]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 07 19:34:26 volumio volumio[964]: info: Setting Spotify Volume from Volumio: 6 Oct 07 19:34:26 volumio volumio[964]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 07 19:34:27 volumio volumio[964]: STREAMING PROXY: Starting server on port 3245 Oct 07 19:34:27 volumio volumio[964]: Node JS runtime: 14 Oct 07 19:34:27 volumio volumio[964]: info: MyVolumio token set successfully Oct 07 19:34:27 volumio volumio[964]: info: MYVOLUMIO: Adding device Oct 07 19:34:27 volumio volumio[964]: info: MYVOLUMIO: Evaluating Server Oct 07 19:34:27 volumio ntpd[1910]: receive: Unexpected origin timestamp 0xeaae9a23.f5f8044c does not match aorg 0000000000.00000000 from server@147.91.8.1 xmt 0xeaae9a23.95a86bb7 Oct 07 19:34:27 volumio volumio[964]: SPOTIFY: SETTING SPOTIFY VOLUME 6 Oct 07 19:34:27 volumio volumio[964]: info: Sending Spotify command with payload to local API: /player/volume Oct 07 19:34:27 volumio volumio[964]: info: MyVolumio status changed Oct 07 19:34:27 volumio volumio[964]: info: Streaming services startup Oct 07 19:34:27 volumio volumio[964]: info: Starting Streaming Daemon Oct 07 19:34:27 volumio volumio[964]: info: Removing browser output: myVolumio user plan is not superstar Oct 07 19:34:27 volumio volumio[964]: info: Removing audio output: Oct 07 19:34:27 volumio volumio[964]: info: Stoppping Tunnel 1 Oct 07 19:34:27 volumio sudo[1944]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 07 19:34:27 volumio sudo[1944]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 07 19:34:27 volumio volumio[964]: error: Failed to ping endpoint eu10.myvolumio.org : unknown error Oct 07 19:34:27 volumio volumio[964]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 07 19:34:27 volumio sudo[1946]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 07 19:34:27 volumio sudo[1946]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 07 19:34:27 volumio sudo[1944]: pam_unix(sudo:session): session closed for user root Oct 07 19:34:27 volumio volumio[964]: Error: Unable to resolve or reject the same promise twice Oct 07 19:34:27 volumio volumio[964]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Oct 07 19:34:27 volumio volumio[964]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32367) Oct 07 19:34:27 volumio volumio[964]: at Socket.emit (events.js:400:28) Oct 07 19:34:27 volumio volumio[964]: at addChunk (internal/streams/readable.js:293:12) Oct 07 19:34:27 volumio volumio[964]: at readableAddChunk (internal/streams/readable.js:267:9) Oct 07 19:34:27 volumio volumio[964]: at Socket.Readable.push (internal/streams/readable.js:206:10) Oct 07 19:34:27 volumio volumio[964]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Oct 07 19:34:27 volumio volumio[964]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 07 19:34:27 volumio sudo[1946]: pam_unix(sudo:session): session closed for user root Oct 07 19:34:28 volumio sudo[1958]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-07 19:33 Oct 07 19:34:28 volumio sudo[1958]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 09:13:11 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ac782621640fcc70c07e91a81b6d958b"