-- Logs begin at Tue 2024-10-29 16:20:36 CET, end at Tue 2024-10-29 16:22:44 CET. -- Oct 29 16:21:00 volumioalrum volumio[1017]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 29 16:21:00 volumioalrum volumio[1017]: info: Initializing connection to go-librespot Websocket Oct 29 16:21:01 volumioalrum volumio[1841]: ...................................................................................++++ Oct 29 16:21:01 volumioalrum volumio[1841]: e is 65537 (0x010001) Oct 29 16:21:01 volumioalrum volumio[1841]: writing RSA key Oct 29 16:21:07 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 29 16:21:08 volumioalrum kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 29 16:21:08 volumioalrum kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Oct 29 16:21:08 volumioalrum sudo[1860]: pam_unix(sudo:session): session closed for user root Oct 29 16:21:08 volumioalrum volumio[1017]: info: Cannot mount NAS VolumioAlrum at system boot, trial number 2 ,retrying in 5 seconds Oct 29 16:21:08 volumioalrum systemd[1]: systemd-fsckd.service: Succeeded. Oct 29 16:21:09 volumioalrum systemd[1]: systemd-hostnamed.service: Succeeded. Oct 29 16:21:13 volumioalrum sudo[1889]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=VolUserAlrum,password=Musik1234,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.100/Musik /mnt/NAS/VolumioAlrum Oct 29 16:21:13 volumioalrum sudo[1889]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 29 16:21:13 volumioalrum kernel: CIFS: Attempting to mount //192.168.1.100/Musik Oct 29 16:21:13 volumioalrum volumio[1017]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.dfs.volumio.org Oct 29 16:21:14 volumioalrum go-librespot[1618]: time="2024-10-29T16:21:14+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" Oct 29 16:21:14 volumioalrum systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 16:21:14 volumioalrum systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 16:21:17 volumioalrum systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 29 16:21:17 volumioalrum systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 29 16:21:17 volumioalrum systemd[1]: Stopped go-librespot Daemon. Oct 29 16:21:17 volumioalrum systemd[1]: Started go-librespot Daemon. Oct 29 16:21:17 volumioalrum go-librespot[1899]: Librespot-go daemon starting... Oct 29 16:21:17 volumioalrum go-librespot[1899]: time="2024-10-29T16:21:17+01:00" level=info msg="generated new device id: ffa77c662144025da199eb03714df909bdfed020" Oct 29 16:21:17 volumioalrum go-librespot[1899]: time="2024-10-29T16:21:17+01:00" level=debug msg="stored credentials found for thietje99" Oct 29 16:21:20 volumioalrum dhcpcd[832]: eth0: offered 192.168.1.101 from 192.168.1.1 Oct 29 16:21:21 volumioalrum dhcpcd[1480]: eth0: offered 192.168.1.101 from 192.168.1.1 Oct 29 16:21:23 volumioalrum sudo[1889]: pam_unix(sudo:session): session closed for user root Oct 29 16:21:23 volumioalrum kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 29 16:21:23 volumioalrum kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Oct 29 16:21:23 volumioalrum volumio[1017]: info: Cannot mount NAS VolumioAlrum at system boot, trial number 3 ,retrying in 5 seconds Oct 29 16:21:23 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 29 16:21:23 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 16:21:23 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 29 16:21:23 volumioalrum volumio[1017]: error: Plugin music_service ytcr failed to complete 'onStart' in a timely fashion Oct 29 16:21:23 volumioalrum volumio[1017]: info: ------------------------------------------- Oct 29 16:21:23 volumioalrum volumio[1017]: info: ----- MyVolumio plugins startup ---- Oct 29 16:21:23 volumioalrum volumio[1017]: info: ------------------------------------------- Oct 29 16:21:23 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 29 16:21:23 volumioalrum volumio[1017]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=x86_amd64&variante=volumio&version=3.757&uuid=d1746440935241e3ca8e6b2ea71fa945" http://updates.volumio.org/downloader-v1/track-device Oct 29 16:21:23 volumioalrum volumio[1017]: % Total % Received % Xferd Average Speed Time Time Time Current Oct 29 16:21:23 volumioalrum volumio[1017]: Dload Upload Total Spent Left Speed Oct 29 16:21:23 volumioalrum volumio[1017]: [1.6K blob data] Oct 29 16:21:23 volumioalrum volumio[1017]: retrying in 5 seconds, trial 0 Oct 29 16:21:23 volumioalrum volumio[1017]: info: Volumio Calling Home Oct 29 16:21:24 volumioalrum dhcpcd[832]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:21:26 volumioalrum dhcpcd[1480]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:21:28 volumioalrum sudo[1912]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=VolUserAlrum,password=Musik1234,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.100/Musik /mnt/NAS/VolumioAlrum Oct 29 16:21:28 volumioalrum sudo[1912]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 29 16:21:28 volumioalrum kernel: CIFS: Attempting to mount //192.168.1.100/Musik Oct 29 16:21:33 volumioalrum volumio[1017]: error: [yt-cast-receiver] (YouTube) Failed to obtain lounge token with screen Id from stored MDX context (749tseq6oqeg8a8hrne57m1gsj): Oct 29 16:21:33 volumioalrum volumio[1017]: (ConnectionError) (YouTube) Connection error in getting lounge token Oct 29 16:21:33 volumioalrum volumio[1017]: Error info: { Oct 29 16:21:33 volumioalrum volumio[1017]: url: 'https://www.youtube.com/api/lounge/pairing/get_lounge_token_batch' Oct 29 16:21:33 volumioalrum volumio[1017]: } Oct 29 16:21:33 volumioalrum volumio[1017]: --->(FetchError) request to https://www.youtube.com/api/lounge/pairing/get_lounge_token_batch failed, reason: getaddrinfo ENOTFOUND www.youtube.com Oct 29 16:21:33 volumioalrum volumio[1017]: Stack trace: Oct 29 16:21:33 volumioalrum volumio[1017]: ConnectionError: (YouTube) Connection error in getting lounge token Oct 29 16:21:33 volumioalrum volumio[1017]: at Session._Session_getLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:435:15) Oct 29 16:21:33 volumioalrum volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Oct 29 16:21:33 volumioalrum volumio[1017]: at async Session.begin (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:131:31) Oct 29 16:21:33 volumioalrum volumio[1017]: at async Promise.all (index 0) Oct 29 16:21:33 volumioalrum volumio[1017]: at async YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:110:13) Oct 29 16:21:33 volumioalrum volumio[1017]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Oct 29 16:21:33 volumioalrum volumio[1017]: Going to generate fresh screen Id and try again... Oct 29 16:21:33 volumioalrum volumio[1017]: error: [yt-cast-receiver] (YouTube Music) Failed to obtain lounge token with screen Id from stored MDX context (ro5lcpnjmp8jdp5mri0490bc8k): Oct 29 16:21:33 volumioalrum volumio[1017]: (ConnectionError) (YouTube Music) Connection error in getting lounge token Oct 29 16:21:33 volumioalrum volumio[1017]: Error info: { Oct 29 16:21:33 volumioalrum volumio[1017]: url: 'https://www.youtube.com/api/lounge/pairing/get_lounge_token_batch' Oct 29 16:21:33 volumioalrum volumio[1017]: } Oct 29 16:21:33 volumioalrum volumio[1017]: --->(FetchError) request to https://www.youtube.com/api/lounge/pairing/get_lounge_token_batch failed, reason: getaddrinfo ENOTFOUND www.youtube.com Oct 29 16:21:33 volumioalrum volumio[1017]: Stack trace: Oct 29 16:21:33 volumioalrum volumio[1017]: ConnectionError: (YouTube Music) Connection error in getting lounge token Oct 29 16:21:33 volumioalrum volumio[1017]: at Session._Session_getLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:435:15) Oct 29 16:21:33 volumioalrum volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Oct 29 16:21:33 volumioalrum volumio[1017]: at async Session.begin (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:131:31) Oct 29 16:21:33 volumioalrum volumio[1017]: at async Promise.all (index 1) Oct 29 16:21:33 volumioalrum volumio[1017]: at async YouTubeApp.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/YouTubeApp.js:110:13) Oct 29 16:21:33 volumioalrum volumio[1017]: at async YouTubeCastReceiver.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/YouTubeCastReceiver.js:91:13) Oct 29 16:21:33 volumioalrum volumio[1017]: Going to generate fresh screen Id and try again... Oct 29 16:21:37 volumioalrum go-librespot[1899]: time="2024-10-29T16:21:37+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" Oct 29 16:21:37 volumioalrum systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 16:21:37 volumioalrum systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 16:21:39 volumioalrum sudo[1912]: pam_unix(sudo:session): session closed for user root Oct 29 16:21:39 volumioalrum kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 29 16:21:39 volumioalrum kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Oct 29 16:21:39 volumioalrum volumio[1017]: info: Cannot mount NAS VolumioAlrum at system boot, trial number 4 ,retrying in 5 seconds Oct 29 16:21:40 volumioalrum systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 29 16:21:40 volumioalrum systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Oct 29 16:21:40 volumioalrum systemd[1]: Stopped go-librespot Daemon. Oct 29 16:21:40 volumioalrum systemd[1]: Started go-librespot Daemon. Oct 29 16:21:40 volumioalrum go-librespot[1960]: Librespot-go daemon starting... Oct 29 16:21:40 volumioalrum go-librespot[1960]: time="2024-10-29T16:21:40+01:00" level=info msg="generated new device id: e12984aaac3c7276dd518091174b20fc4b5a135a" Oct 29 16:21:40 volumioalrum go-librespot[1960]: time="2024-10-29T16:21:40+01:00" level=debug msg="stored credentials found for thietje99" Oct 29 16:21:43 volumioalrum volumio[1017]: error: MyVolumio Plugin failed to start in a timely fashion Oct 29 16:21:43 volumioalrum volumio[1017]: info: BOOT COMPLETED Oct 29 16:21:43 volumioalrum volumio[1017]: [Metrics] CommandRouter: 61s 21.22ms Oct 29 16:21:43 volumioalrum volumio[1017]: info: CoreCommandRouter::volumiosetStartupVolume Oct 29 16:21:43 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 29 16:21:43 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 16:21:43 volumioalrum volumio[1017]: info: CoreCommandRouter::Close All Modals sent Oct 29 16:21:43 volumioalrum volumio[1017]: info: CoreCommandRouter::Close All Modals sent Oct 29 16:21:44 volumioalrum sudo[1970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=VolUserAlrum,password=Musik1234,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.100/Musik /mnt/NAS/VolumioAlrum Oct 29 16:21:44 volumioalrum sudo[1970]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 29 16:21:44 volumioalrum kernel: CIFS: Attempting to mount //192.168.1.100/Musik Oct 29 16:21:44 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 29 16:21:44 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 29 16:21:44 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 29 16:21:46 volumioalrum dhcpcd[832]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:21:50 volumioalrum dhcpcd[1480]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:21:53 volumioalrum volumio[1017]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=x86_amd64&variante=volumio&version=3.757&uuid=d1746440935241e3ca8e6b2ea71fa945" http://updates.volumio.org/downloader-v1/track-device Oct 29 16:21:53 volumioalrum volumio[1017]: % Total % Received % Xferd Average Speed Time Time Time Current Oct 29 16:21:53 volumioalrum volumio[1017]: Dload Upload Total Spent Left Speed Oct 29 16:21:53 volumioalrum volumio[1017]: [1.6K blob data] Oct 29 16:21:53 volumioalrum volumio[1017]: retrying in 5 seconds, trial 1 Oct 29 16:21:53 volumioalrum volumio[1017]: info: Volumio Calling Home Oct 29 16:21:54 volumioalrum sudo[1970]: pam_unix(sudo:session): session closed for user root Oct 29 16:21:54 volumioalrum kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Oct 29 16:21:54 volumioalrum kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Oct 29 16:21:54 volumioalrum volumio[1017]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 29 16:22:00 volumioalrum go-librespot[1960]: time="2024-10-29T16:22:00+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" Oct 29 16:22:00 volumioalrum systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 16:22:00 volumioalrum systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 16:22:03 volumioalrum systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 29 16:22:03 volumioalrum systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 29 16:22:03 volumioalrum systemd[1]: Stopped go-librespot Daemon. Oct 29 16:22:03 volumioalrum systemd[1]: Started go-librespot Daemon. Oct 29 16:22:03 volumioalrum go-librespot[1980]: Librespot-go daemon starting... Oct 29 16:22:03 volumioalrum go-librespot[1980]: time="2024-10-29T16:22:03+01:00" level=info msg="generated new device id: a13c199010f474c69488d61aaa2f310b78b5a83a" Oct 29 16:22:03 volumioalrum go-librespot[1980]: time="2024-10-29T16:22:03+01:00" level=debug msg="stored credentials found for thietje99" Oct 29 16:22:06 volumioalrum ntpd[1003]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Oct 29 16:22:13 volumioalrum volumio[1017]: info: Discovery: adding d016a4a5-e68e-44ec-998d-33514b24f501 Oct 29 16:22:13 volumioalrum volumio[1017]: info: Discovery: Found device VolumioAlrum Oct 29 16:22:13 volumioalrum volumio[1017]: info: CoreCommandRouter::volumioGetState Oct 29 16:22:13 volumioalrum volumio[1017]: info: CorePlayQueue::getTrack 0 Oct 29 16:22:13 volumioalrum go-librespot[1980]: time="2024-10-29T16:22:13+01:00" level=debug msg="new websocket client" Oct 29 16:22:13 volumioalrum volumio[1017]: info: Connection to go-librespot Websocket established Oct 29 16:22:16 volumioalrum volumio[1017]: info: Getting Spotify volume Oct 29 16:22:23 volumioalrum go-librespot[1980]: time="2024-10-29T16:22:23+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" Oct 29 16:22:23 volumioalrum systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 29 16:22:23 volumioalrum systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 29 16:22:23 volumioalrum volumio[1017]: (node:1017) UnhandledPromiseRejectionWarning: Error: socket hang up Oct 29 16:22:23 volumioalrum volumio[1017]: at connResetException (internal/errors.js:639:14) Oct 29 16:22:23 volumioalrum volumio[1017]: at Socket.socketOnEnd (_http_client.js:499:23) Oct 29 16:22:23 volumioalrum volumio[1017]: at Socket.emit (events.js:412:35) Oct 29 16:22:23 volumioalrum volumio[1017]: at endReadableNT (internal/streams/readable.js:1333:12) Oct 29 16:22:23 volumioalrum volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Oct 29 16:22:23 volumioalrum volumio[1017]: (Use `node --trace-warnings ...` to show where the warning was created) Oct 29 16:22:23 volumioalrum volumio[1017]: (node:1017) 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: 2) Oct 29 16:22:23 volumioalrum volumio[1017]: (node:1017) [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. Oct 29 16:22:23 volumioalrum volumio[1017]: info: Connection to go-librespot Websocket closed Oct 29 16:22:23 volumioalrum volumio[1017]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=x86_amd64&variante=volumio&version=3.757&uuid=d1746440935241e3ca8e6b2ea71fa945" http://updates.volumio.org/downloader-v1/track-device Oct 29 16:22:23 volumioalrum volumio[1017]: % Total % Received % Xferd Average Speed Time Time Time Current Oct 29 16:22:23 volumioalrum volumio[1017]: Dload Upload Total Spent Left Speed Oct 29 16:22:23 volumioalrum volumio[1017]: [1.6K blob data] Oct 29 16:22:23 volumioalrum volumio[1017]: retrying in 5 seconds, trial 2 Oct 29 16:22:23 volumioalrum volumio[1017]: info: Volumio Calling Home Oct 29 16:22:26 volumioalrum ntpd[1003]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Oct 29 16:22:26 volumioalrum volumio[1017]: info: Initializing connection to go-librespot Websocket Oct 29 16:22:26 volumioalrum systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 29 16:22:26 volumioalrum systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 29 16:22:26 volumioalrum systemd[1]: Stopped go-librespot Daemon. Oct 29 16:22:27 volumioalrum systemd[1]: Started go-librespot Daemon. Oct 29 16:22:27 volumioalrum go-librespot[1991]: Librespot-go daemon starting... Oct 29 16:22:27 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:27+01:00" level=info msg="generated new device id: a171ec244360cc20ad1eca5f89e87ba730aa683c" Oct 29 16:22:27 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:27+01:00" level=debug msg="stored credentials found for thietje99" Oct 29 16:22:28 volumioalrum dhcpcd[1480]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:22:28 volumioalrum dhcpcd[832]: eth0: ignoring offer of 192.168.1.101 from 192.168.1.1 Oct 29 16:22:30 volumioalrum dhcpcd[832]: eth0: probing address 192.168.1.101/24 Oct 29 16:22:30 volumioalrum dhcpcd[1480]: eth0: probing address 192.168.1.101/24 Oct 29 16:22:33 volumioalrum volumio[1017]: 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 29 16:22:34 volumioalrum dhcpcd[832]: eth0: leased 192.168.1.101 for 86400 seconds Oct 29 16:22:34 volumioalrum dhcpcd[832]: eth0: adding route to 192.168.1.0/24 Oct 29 16:22:34 volumioalrum dhcpcd[832]: eth0: changing default route via 192.168.1.1 Oct 29 16:22:34 volumioalrum avahi-daemon[758]: Registering new address record for 192.168.1.101 on eth0.IPv4. Oct 29 16:22:34 volumioalrum dhcpcd[1480]: eth0: deleted default route Oct 29 16:22:34 volumioalrum ntpd[1003]: ntpd exiting on signal 15 (Terminated) Oct 29 16:22:34 volumioalrum systemd[1]: Stopping Network Time Service... Oct 29 16:22:34 volumioalrum systemd[1]: ntp.service: Succeeded. Oct 29 16:22:34 volumioalrum systemd[1]: Stopped Network Time Service. Oct 29 16:22:34 volumioalrum systemd[1]: Starting Network Time Service... Oct 29 16:22:34 volumioalrum ntpd[2032]: ntpd 4.2.8p12@1.3728-o (1): Starting Oct 29 16:22:34 volumioalrum systemd[1]: Started Network Time Service. Oct 29 16:22:34 volumioalrum ntpd[2032]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Oct 29 16:22:34 volumioalrum ntpd[2038]: proto: precision = 0.188 usec (-22) Oct 29 16:22:34 volumioalrum dhcpcd[832]: eth0: deleting route to 169.254.0.0/16 Oct 29 16:22:34 volumioalrum ntpd[2038]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Oct 29 16:22:34 volumioalrum ntpd[2038]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Oct 29 16:22:34 volumioalrum ntpd[2038]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 672 days ago Oct 29 16:22:34 volumioalrum ntpd[2038]: Listen and drop on 0 v6wildcard [::]:123 Oct 29 16:22:34 volumioalrum ntpd[2038]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Oct 29 16:22:34 volumioalrum ntpd[2038]: Listen normally on 2 lo 127.0.0.1:123 Oct 29 16:22:34 volumioalrum ntpd[2038]: Listen normally on 3 eth0 192.168.1.101:123 Oct 29 16:22:34 volumioalrum ntpd[2038]: Listening on routing socket on fd #20 for interface updates Oct 29 16:22:34 volumioalrum ntpd[2038]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 29 16:22:34 volumioalrum ntpd[2038]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 29 16:22:34 volumioalrum avahi-daemon[758]: Withdrawing address record for 169.254.251.118 on eth0. Oct 29 16:22:34 volumioalrum avahi-daemon[758]: Leaving mDNS multicast group on interface eth0.IPv4 with address 169.254.251.118. Oct 29 16:22:34 volumioalrum avahi-daemon[758]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.101. Oct 29 16:22:34 volumioalrum dhcpcd[1480]: eth0: deleted route to 169.254.0.0/16 Oct 29 16:22:34 volumioalrum dhcpcd[1480]: eth0: adding route to 169.254.0.0/16 Oct 29 16:22:34 volumioalrum dhcpcd[1480]: if_route (ADD): Invalid argument Oct 29 16:22:34 volumioalrum dhcpcd[1480]: eth0: adding default route Oct 29 16:22:34 volumioalrum dhcpcd[1480]: if_route (ADD): Invalid argument Oct 29 16:22:35 volumioalrum ntpd[2038]: Soliciting pool server 95.154.26.34 Oct 29 16:22:35 volumioalrum dhcpcd[1480]: eth0: leased 192.168.1.101 for 86400 seconds Oct 29 16:22:35 volumioalrum dhcpcd[1480]: eth0: adding route to 192.168.1.0/24 Oct 29 16:22:35 volumioalrum dhcpcd[1480]: eth0: adding default route via 192.168.1.1 Oct 29 16:22:35 volumioalrum dhcpcd[1480]: eth0: adding route to 169.254.0.0/16 Oct 29 16:22:35 volumioalrum dhcpcd[1480]: if_route (ADD): Invalid argument Oct 29 16:22:35 volumioalrum ntpd[2038]: ntpd exiting on signal 15 (Terminated) Oct 29 16:22:35 volumioalrum ntpd[2038]: 95.154.26.34 local addr 192.168.1.101 -> Oct 29 16:22:35 volumioalrum systemd[1]: Stopping Network Time Service... Oct 29 16:22:35 volumioalrum systemd[1]: ntp.service: Succeeded. Oct 29 16:22:35 volumioalrum systemd[1]: Stopped Network Time Service. Oct 29 16:22:35 volumioalrum systemd[1]: Starting Network Time Service... Oct 29 16:22:35 volumioalrum ntpd[2085]: ntpd 4.2.8p12@1.3728-o (1): Starting Oct 29 16:22:35 volumioalrum ntpd[2085]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Oct 29 16:22:35 volumioalrum systemd[1]: Started Network Time Service. Oct 29 16:22:35 volumioalrum ntpd[2091]: proto: precision = 0.200 usec (-22) Oct 29 16:22:35 volumioalrum ntpd[2091]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Oct 29 16:22:35 volumioalrum ntpd[2091]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Oct 29 16:22:35 volumioalrum ntpd[2091]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 672 days ago Oct 29 16:22:35 volumioalrum ntpd[2091]: Listen and drop on 0 v6wildcard [::]:123 Oct 29 16:22:35 volumioalrum ntpd[2091]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Oct 29 16:22:35 volumioalrum ntpd[2091]: Listen normally on 2 lo 127.0.0.1:123 Oct 29 16:22:35 volumioalrum ntpd[2091]: Listen normally on 3 eth0 192.168.1.101:123 Oct 29 16:22:35 volumioalrum ntpd[2091]: Listening on routing socket on fd #20 for interface updates Oct 29 16:22:35 volumioalrum ntpd[2091]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 29 16:22:35 volumioalrum ntpd[2091]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 29 16:22:36 volumioalrum ntpd[2091]: Soliciting pool server 86.52.112.177 Oct 29 16:22:37 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:37+01:00" level=debug msg="obtained new client token: AAAx1zpCpEexoai+oMge9im2+P5tCkTwhqG4Hijh/jDxNGcXogEaYDVphr3brHc/pBqTdYYB+y8GwDLL7MctKf7mDecot5RXnveSM9/5fgQspCkYZIx1I6dmN989ae37WfGMvCEev/HSPbyetnX4eGJPGEXqt1RDBCNg1aEfWeNVtnMI6Lsc7ORQHUiqZmbyZauE82dD1K1Q288BRAcrM1paLQ7YTwY7b45gQTL86pyw3MJFGh4PB+HgoSrwp3A=" Oct 29 16:22:37 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 29 16:22:37 volumioalrum ntpd[2091]: Soliciting pool server 78.156.124.235 Oct 29 16:22:37 volumioalrum ntpd[2091]: Soliciting pool server 217.198.219.102 Oct 29 16:22:37 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:37+01:00" level=debug msg="completed keyexchange" Oct 29 16:22:37 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 29 16:22:37 volumioalrum volumio[1017]: info: Received Get System Info Oct 29 16:22:37 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 29 16:22:37 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 29 16:22:37 volumioalrum volumio[1017]: info: Discovery: Getting this device information Oct 29 16:22:37 volumioalrum volumio[1017]: info: CoreCommandRouter::volumioGetState Oct 29 16:22:37 volumioalrum volumio[1017]: info: CorePlayQueue::getTrack 0 Oct 29 16:22:37 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="completed challenge" Oct 29 16:22:38 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="authenticated as thietje99" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="authenticated as thietje99" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 29 16:22:38 volumioalrum ntpd[2091]: Soliciting pool server 193.200.91.90 Oct 29 16:22:38 volumioalrum ntpd[2091]: Soliciting pool server 5.186.224.242 Oct 29 16:22:38 volumioalrum volumio[1017]: 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 29 16:22:38 volumioalrum volumio[1017]: 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 29 16:22:38 volumioalrum volumio[1017]: 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 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="new websocket client" Oct 29 16:22:38 volumioalrum volumio[1017]: info: Connection to go-librespot Websocket established Oct 29 16:22:38 volumioalrum volumio[1017]: 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 29 16:22:38 volumioalrum volumio[1017]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="dealer connection opened" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 29 16:22:38 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:38+01:00" level=debug msg="received connection id: YWFiMzI4YzUtM2MxMS00NzE5LWJjNzEtODg5Y2M2NGQ1MTJlK2RlYWxlcit0Y3A6Ly8wYWNhNTkxMi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArODdCQTc5NUM3MThBMTBERDc0QUQ3RjI5NTc5RUM3NkZCMDZERDg1NkZENDg1MUIxQTc1OTczNUUyMEIzQjgxOA==" Oct 29 16:22:39 volumioalrum volumio[1017]: info: CoreCommandRouter::volumioGetState Oct 29 16:22:39 volumioalrum volumio[1017]: info: CorePlayQueue::getTrack 0 Oct 29 16:22:39 volumioalrum volumio[1017]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Oct 29 16:22:39 volumioalrum volumio[1017]: SPOTIFY: SPOTIFY VOLUME undefined Oct 29 16:22:39 volumioalrum volumio[1017]: SPOTIFY: VOLUMIO VOLUME 86 Oct 29 16:22:39 volumioalrum volumio[1017]: info: Aligning Spotify Volume to Volumio Volume Oct 29 16:22:39 volumioalrum volumio[1017]: info: CoreCommandRouter::volumioGetState Oct 29 16:22:39 volumioalrum volumio[1017]: info: CorePlayQueue::getTrack 0 Oct 29 16:22:39 volumioalrum volumio[1017]: info: Setting Spotify Volume from Volumio: 86 Oct 29 16:22:39 volumioalrum ntpd[2091]: Soliciting pool server 94.147.59.27 Oct 29 16:22:39 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:39+01:00" level=debug msg="put connect state because NEW_DEVICE" Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin bluetooth to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin multiroom to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin metavolumio to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin cd_controller to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 29 16:22:39 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 29 16:22:39 volumioalrum ntpd[2091]: Soliciting pool server 192.36.143.130 Oct 29 16:22:39 volumioalrum ntpd[2091]: Soliciting pool server 80.209.68.118 Oct 29 16:22:39 volumioalrum ntpd[2091]: Soliciting pool server 95.154.26.34 Oct 29 16:22:39 volumioalrum ntpd[2091]: Soliciting pool server 162.159.200.123 Oct 29 16:22:40 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 29 16:22:40 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 29 16:22:40 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 16:22:40 volumioalrum volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 29 16:22:40 volumioalrum volumio[1017]: info: Starting MyVolumio Remote Streaming Endpoints Oct 29 16:22:40 volumioalrum volumio[1017]: info: MyVolumio login type: Token Oct 29 16:22:40 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 29 16:22:40 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 29 16:22:40 volumioalrum ntpd[2091]: Soliciting pool server 87.104.58.9 Oct 29 16:22:40 volumioalrum ntpd[2091]: Soliciting pool server 162.159.200.1 Oct 29 16:22:40 volumioalrum ntpd[2091]: Soliciting pool server 192.121.118.98 Oct 29 16:22:40 volumioalrum ntpd[2091]: Soliciting pool server 185.181.223.169 Oct 29 16:22:41 volumioalrum volumio[1017]: info: Starting Streaming Service Transparent Proxy Oct 29 16:22:41 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 29 16:22:41 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 29 16:22:41 volumioalrum volumio[1017]: info: Streaming services startup Oct 29 16:22:41 volumioalrum volumio[1017]: info: Starting Streaming Daemon Oct 29 16:22:41 volumioalrum sudo[2166]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 16:22:41 volumioalrum sudo[2166]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 29 16:22:41 volumioalrum sudo[2166]: pam_unix(sudo:session): session closed for user root Oct 29 16:22:41 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 29 16:22:41 volumioalrum volumio[1017]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Oct 29 16:22:41 volumioalrum volumio[1017]: info: Sending Spotify command with payload to local API: /player/volume Oct 29 16:22:41 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:41+01:00" level=debug msg="update volume to 56360/65535" Oct 29 16:22:41 volumioalrum volumio[1017]: error: Cannot start Volumio Streaming Daemon Oct 29 16:22:41 volumioalrum volumio[1017]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 29 16:22:41 volumioalrum volumio[1017]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 29 16:22:41 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:41+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 29 16:22:41 volumioalrum go-librespot[1991]: time="2024-10-29T16:22:41+01:00" level=trace msg="emitting websocket event: volume" Oct 29 16:22:41 volumioalrum volumio[1017]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Oct 29 16:22:41 volumioalrum volumio[1017]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Oct 29 16:22:41 volumioalrum ntpd[2091]: Soliciting pool server 217.116.227.3 Oct 29 16:22:41 volumioalrum ntpd[2091]: Soliciting pool server 2a00:1f98:1001::123 Oct 29 16:22:41 volumioalrum ntpd[2091]: Soliciting pool server 213.5.39.34 Oct 29 16:22:41 volumioalrum volumio[1017]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 29 16:22:41 volumioalrum volumio[1017]: error: MyVolumio Custom Token format not valid, refreshing it Oct 29 16:22:41 volumioalrum volumio[1017]: info: Getting Spotify volume Oct 29 16:22:41 volumioalrum volumio[1017]: info: Spotify volume: 86 Oct 29 16:22:41 volumioalrum volumio[1017]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 29 16:22:42 volumioalrum volumio[1017]: info: CoreCommandRouter::volumioGetState Oct 29 16:22:42 volumioalrum volumio[1017]: info: CorePlayQueue::getTrack 0 Oct 29 16:22:42 volumioalrum volumio[1017]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Oct 29 16:22:42 volumioalrum volumio[1017]: STREAMING PROXY: Starting server on port 3245 Oct 29 16:22:42 volumioalrum volumio[1017]: Node JS runtime: 14 Oct 29 16:22:42 volumioalrum volumio[1017]: info: MyVolumio login type: Token Oct 29 16:22:42 volumioalrum ntpd[2091]: Soliciting pool server 212.99.225.86 Oct 29 16:22:42 volumioalrum ntpd[2091]: Soliciting pool server 213.32.246.229 Oct 29 16:22:43 volumioalrum volumio[1017]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 29 16:22:44 volumioalrum volumio[1017]: info: MyVolumio token set successfully Oct 29 16:22:44 volumioalrum volumio[1017]: info: MYVOLUMIO: Adding device Oct 29 16:22:44 volumioalrum volumio[1017]: info: MYVOLUMIO: Evaluating Server Oct 29 16:22:44 volumioalrum volumio[1017]: info: MyVolumio Plan changed: premium Oct 29 16:22:44 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Oct 29 16:22:44 volumioalrum volumio[1017]: info: Removing browser output: myVolumio user plan is not superstar Oct 29 16:22:44 volumioalrum volumio[1017]: info: Removing audio output: Oct 29 16:22:44 volumioalrum volumio[1017]: info: MYVOLUMIO: Adding device Oct 29 16:22:44 volumioalrum volumio[1017]: info: MYVOLUMIO: Evaluating Server Oct 29 16:22:44 volumioalrum volumio[1017]: info: Remote config written successfully Oct 29 16:22:44 volumioalrum volumio[1017]: info: Starting Tunnel 1 Oct 29 16:22:44 volumioalrum volumio[1017]: info: Starting Tunnel Connection Checker Oct 29 16:22:42 volumioalrum ntpd[2091]: receive: Unexpected origin timestamp 0xeacb7c44.d135a303 does not match aorg 0000000000.00000000 from server@94.147.59.27 xmt 0xeacb7c42.2704f3c8 Oct 29 16:22:42 volumioalrum volumio[1017]: info: MYVolumio Device enabled Oct 29 16:22:42 volumioalrum volumio[1017]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Oct 29 16:22:42 volumioalrum volumio[1017]: info: MyVolumio status changed Oct 29 16:22:42 volumioalrum volumio[1017]: info: Streaming services startup Oct 29 16:22:42 volumioalrum volumio[1017]: info: Starting Streaming Daemon Oct 29 16:22:42 volumioalrum sudo[2206]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 29 16:22:42 volumioalrum sudo[2206]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 29 16:22:42 volumioalrum volumio[1017]: error: Failed to ping endpoint as1.myvolumio.org : unknown error Oct 29 16:22:42 volumioalrum volumio[1017]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 16:22:42 volumioalrum volumio[1017]: Error: Unable to resolve or reject the same promise twice Oct 29 16:22:42 volumioalrum volumio[1017]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Oct 29 16:22:42 volumioalrum volumio[1017]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32086) Oct 29 16:22:42 volumioalrum volumio[1017]: at Socket.emit (events.js:412:35) Oct 29 16:22:42 volumioalrum volumio[1017]: at endReadableNT (internal/streams/readable.js:1333:12) Oct 29 16:22:42 volumioalrum volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Oct 29 16:22:42 volumioalrum volumio[1017]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 29 16:22:42 volumioalrum sudo[2206]: pam_unix(sudo:session): session closed for user root Oct 29 16:22:42 volumioalrum sudo[2217]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-29 16:21 Oct 29 16:22:42 volumioalrum sudo[2217]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"