Jul 08 16:31:04 volumio1920x480 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 16:31:04 volumio1920x480 dbus-daemon[876]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.59' (uid=0 pid=4052 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 16:31:04 volumio1920x480 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 16:31:04 volumio1920x480 dbus-daemon[876]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 16:31:04 volumio1920x480 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 16:31:04 volumio1920x480 setdatetime-helper.sh[4051]: Time is not synchronized. Attempting to sync... Jul 08 16:31:04 volumio1920x480 sudo[4060]: root : unable to resolve host volumio1920x480: System error Jul 08 16:31:04 volumio1920x480 setdatetime-helper.sh[4060]: sudo: unable to resolve host volumio1920x480: System error Jul 08 16:31:04 volumio1920x480 sudo[4060]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 08 Jul 2025 14:31:05 GMT#015' Jul 08 16:31:04 volumio1920x480 sudo[4060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 08 16:31:05 volumio1920x480 setdatetime-helper.sh[4061]: Tue Jul 8 16:31:05 CEST 2025 Jul 08 16:31:05 volumio1920x480 sudo[4060]: pam_unix(sudo:session): session closed for user root Jul 08 16:31:05 volumio1920x480 setdatetime-helper.sh[4051]: Time synchronized successfully. Jul 08 16:31:05 volumio1920x480 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 16:31:05 volumio1920x480 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: Discovery: Getting this device information Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetState Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:31:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:31:15 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:15+02:00" level=trace msg="sent dealer ping" Jul 08 16:31:15 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:15+02:00" level=trace msg="received dealer pong" Jul 08 16:31:34 volumio1920x480 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: Discovery: Getting this device information Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetState Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:31:41 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:31:44 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:44+02:00" level=trace msg="received accesspoint ping" Jul 08 16:31:44 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:44+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:31:45 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:45+02:00" level=trace msg="sent dealer ping" Jul 08 16:31:45 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:31:45+02:00" level=trace msg="received dealer pong" Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: Discovery: Getting this device information Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetState Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:11 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:32:15 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:15+02:00" level=trace msg="sent dealer ping" Jul 08 16:32:15 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:15+02:00" level=trace msg="received dealer pong" Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Preload queue cleared Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::ClearQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::clearPlayQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::saveQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::addQueueItems Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::addQueueItems Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Preload queue cleared Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3w0eFAME3IxlonearUIaXJ Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3w0eFAME3IxlonearUIaXJ Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4sm7xhaW2PT4iLuTtXaKa1 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4sm7xhaW2PT4iLuTtXaKa1 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:54HwZc6fEmR5EnjRT4oBq5 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:54HwZc6fEmR5EnjRT4oBq5 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:0BzX5iHjzOJw3j9xK4B5pq Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:0BzX5iHjzOJw3j9xK4B5pq Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:05lhFsOWPXRjfGA7xY7XJz Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:05lhFsOWPXRjfGA7xY7XJz Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::saveQueue Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::updateTrackBlock Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrackBlock Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPlay Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index 4 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CoreStateMachine::addQueueItems Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: CorePlayQueue::addQueueItems Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Preload queue cleared Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:65cRt4uGMzo51AzXqptVsX Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:65cRt4uGMzo51AzXqptVsX Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3yaMisjmccUHlzZYgSh9zf Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3yaMisjmccUHlzZYgSh9zf Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3wdV4OJ37JdoLyUJMm50UW Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3wdV4OJ37JdoLyUJMm50UW Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:5GyaXqMfcIGHfmTUITFacS Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:5GyaXqMfcIGHfmTUITFacS Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:6dmuFoJ8jYh7kzai2twWNo Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:6dmuFoJ8jYh7kzai2twWNo Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:5G5R93fhTnLMXVcoIO6QNa Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:5G5R93fhTnLMXVcoIO6QNa Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:63cOYqSjpQXEBrMTkBQwrp Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:63cOYqSjpQXEBrMTkBQwrp Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:56lGvDVasowdpufZnBJbuB Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:56lGvDVasowdpufZnBJbuB Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:06ANwmMgiOcgBtaxFiPuKk Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:06ANwmMgiOcgBtaxFiPuKk Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4XHrQHvHWlE0RldeG8Nslq Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4XHrQHvHWlE0RldeG8Nslq Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:07eJSSPcNlkR34wVlkrCcY Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:07eJSSPcNlkR34wVlkrCcY Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2iCI6gHilTbSiD8a138KMU Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2iCI6gHilTbSiD8a138KMU Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4WnlAkJ3S0r6C7ofHy6kNP Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4WnlAkJ3S0r6C7ofHy6kNP Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4DREBgUie15tAPq9KQqe2c Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4DREBgUie15tAPq9KQqe2c Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:5nmYNuBSh99LNDdZ0iSe2O Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:5nmYNuBSh99LNDdZ0iSe2O Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:5LDB1Cal2PnHN3Ioy84SdN Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:5LDB1Cal2PnHN3Ioy84SdN Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:52ZxqHSe1HesJPwuuBiW4U Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:52ZxqHSe1HesJPwuuBiW4U Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:7msfmSm4KbVnIds5DvsGzT Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:7msfmSm4KbVnIds5DvsGzT Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:6Uh5S2WjXoFPkgcVHaQV0d Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:6Uh5S2WjXoFPkgcVHaQV0d Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2pNjk1fIZTMtj8ry6SdEmB Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2pNjk1fIZTMtj8ry6SdEmB Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:0mCxHKr5bp05PMdD7jU4rW Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:0mCxHKr5bp05PMdD7jU4rW Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:1136eJrkWsDvReASbjLTaU Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:1136eJrkWsDvReASbjLTaU Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:7L1DT2ByQ331AJkDfjvI5N Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:7L1DT2ByQ331AJkDfjvI5N Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3RMr94P81nO3GtW9MfqNp5 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3RMr94P81nO3GtW9MfqNp5 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:75NaRkat24l3uKOyfymyzJ Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:75NaRkat24l3uKOyfymyzJ Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3ZR7IlqBPK8TrJyZYfFX9L Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3ZR7IlqBPK8TrJyZYfFX9L Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:0OWPr4POCQ7iH9BGmTxOZV Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:0OWPr4POCQ7iH9BGmTxOZV Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:5hphSVebVxTpDfrk09W0hS Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:5hphSVebVxTpDfrk09W0hS Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:20l4NPs2c9OBKBKUKRjxIy Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:20l4NPs2c9OBKBKUKRjxIy Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:6zZixF6uYbtG8uiNzDO2LH Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:6zZixF6uYbtG8uiNzDO2LH Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2hODYSmDyWMu2C2XN4bgOV Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2hODYSmDyWMu2C2XN4bgOV Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:0SmcKaXjPCCK7nq0coN6B2 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:0SmcKaXjPCCK7nq0coN6B2 Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:7mdvPu1ZAOIgMzr3sfpAqk Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:7mdvPu1ZAOIgMzr3sfpAqk Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4FMfmvlC2DpXIQmpYpcdlC Jul 08 16:32:21 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4FMfmvlC2DpXIQmpYpcdlC Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:1xFkc8KXwVk1FoG5xhcU3H Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:1xFkc8KXwVk1FoG5xhcU3H Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2GSK9VfsKWpVOV6ZzKiMA4 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2GSK9VfsKWpVOV6ZzKiMA4 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:00uXDC6A3RK2HJlTK6h0Ak Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:00uXDC6A3RK2HJlTK6h0Ak Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2JkIrQmiFXvqYQHhnPiY5D Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2JkIrQmiFXvqYQHhnPiY5D Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:6NOrpcicPUh2eaj8bAD44u Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:6NOrpcicPUh2eaj8bAD44u Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:78lEwmE6xpWtwHhS8D9Fw2 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:78lEwmE6xpWtwHhS8D9Fw2 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2v7r3nItoWRbCQBS1qFQnD Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2v7r3nItoWRbCQBS1qFQnD Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:2YwBdxvMFsWUSCaL1U6xIg Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:2YwBdxvMFsWUSCaL1U6xIg Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:4uLBwGnr1U3ctcDZrnVEgK Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:4uLBwGnr1U3ctcDZrnVEgK Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:1N8G6PUj14v0VG8evbRSxp Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:1N8G6PUj14v0VG8evbRSxp Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:0syyMKF0pQ8psk6aPNTh7N Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:0syyMKF0pQ8psk6aPNTh7N Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CorePlayQueue::saveQueue Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index undefined Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::updateTrackBlock Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrackBlock Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 4 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 4 Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: [1751985142009] ControllerSpotify::clearAddPlayTrack Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="resolved context of track" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:32:22 volumio1920x480 volumio[1383]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:05lhFsOWPXRjfGA7xY7XJz","play_origin":"go-librespot"}} Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (98584ffa0b2deaadcd9cd86f1a5a5adec11b1470)" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="requested aes key for file 98584ffa0b2deaadcd9cd86f1a5a5adec11b1470, gid: 05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="fetched first chunk of 15, total size is 7406636 bytes" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="created new output device" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: time="2025-07-08T16:32:22+02:00" level=info msg="loaded track \"Pressure\" (paused: false, position: 0ms, duration: 159994ms, prefetched: false)" uri="spotify:track:05lhFsOWPXRjfGA7xY7XJz" Jul 08 16:32:22 volumio1920x480 go-librespot[3906]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:32:22 volumio1920x480 go-librespot[3905]: Aborted Jul 08 16:32:22 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:32:22 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:32:22 volumio1920x480 volumio[1383]: info: Connection to go-librespot Websocket closed Jul 08 16:32:22 volumio1920x480 volumio[1383]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:32:22 volumio1920x480 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 16:32:22 volumio1920x480 dbus-daemon[876]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.61' (uid=0 pid=4181 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 16:32:22 volumio1920x480 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 16:32:22 volumio1920x480 dbus-daemon[876]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 16:32:22 volumio1920x480 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 16:32:22 volumio1920x480 setdatetime-helper.sh[4180]: Time is not synchronized. Attempting to sync... Jul 08 16:32:22 volumio1920x480 sudo[4189]: root : unable to resolve host volumio1920x480: System error Jul 08 16:32:22 volumio1920x480 setdatetime-helper.sh[4189]: sudo: unable to resolve host volumio1920x480: System error Jul 08 16:32:22 volumio1920x480 sudo[4189]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 08 Jul 2025 14:32:22 GMT#015' Jul 08 16:32:22 volumio1920x480 sudo[4189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 08 16:32:22 volumio1920x480 setdatetime-helper.sh[4190]: Tue Jul 8 16:32:22 CEST 2025 Jul 08 16:32:22 volumio1920x480 sudo[4189]: pam_unix(sudo:session): session closed for user root Jul 08 16:32:22 volumio1920x480 setdatetime-helper.sh[4180]: Time synchronized successfully. Jul 08 16:32:22 volumio1920x480 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 16:32:22 volumio1920x480 systemd-journald[427]: Time jumped backwards, rotating. Jul 08 16:32:22 volumio1920x480 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPlay Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index undefined Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 4 Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 4 Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: [1751985143837] ControllerSpotify::clearAddPlayTrack Jul 08 16:32:23 volumio1920x480 volumio[1383]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:32:23 volumio1920x480 volumio[1383]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:32:24 volumio1920x480 volumio[1383]: info: Initializing connection to go-librespot Websocket Jul 08 16:32:24 volumio1920x480 volumio[1383]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:32:24 volumio1920x480 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jul 08 16:32:24 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:32:24 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:32:24 volumio1920x480 go-librespot[4192]: go-librespot daemon starting... Jul 08 16:32:24 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:24+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:32:24 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:24+02:00" level=debug msg="app state loaded" Jul 08 16:32:24 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02: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]" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02: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]" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=info msg="zeroconf server listening on port 36913" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="obtained new client token: AAD/z/SEyVJl5duMrwjkK2Vh3BqDDpHxuxMgRMQSu6S1z4WDmZk4OfUN33SHHBIMouGLdNe7aVcKXyqAvyyYlBKomjHHmjRmjsmCVysybWCWO6mbk++ld3R5Unb3V6l4ZLptFKL8+DHg0L3NBOuyttc7XTJAFBozToaxEJX/1hE1Wz2FpP7OBPof8OZEna8SMAcAsNsXJKwy4t/wAy7nYUByz9uSkA6zAkw6gQ0PjholJW07xkQScV4=" Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioNext Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::next Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index undefined Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 5 Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 5 Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: [1751985145142] ControllerSpotify::clearAddPlayTrack Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CoreStateMachine::updateTrackBlock Jul 08 16:32:25 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrackBlock Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="completed keyexchange" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="completed challenge" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="dealer connection opened" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=trace msg="received accesspoint ping" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="resolved context of track" uri="spotify:track:65cRt4uGMzo51AzXqptVsX" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:65cRt4uGMzo51AzXqptVsX" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:65cRt4uGMzo51AzXqptVsX" Jul 08 16:32:25 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:25+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 16:32:26 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:26+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:32:27 volumio1920x480 volumio[1383]: info: Initializing connection to go-librespot Websocket Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=debug msg="new websocket client" Jul 08 16:32:27 volumio1920x480 volumio[1383]: info: Connection to go-librespot Websocket established Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=debug msg="selected format OGG_VORBIS_320 (314cdf18e6f175d1dd0b5a273bb4520413c8b650)" uri="spotify:track:65cRt4uGMzo51AzXqptVsX" Jul 08 16:32:27 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:27+02:00" level=debug msg="requested aes key for file 314cdf18e6f175d1dd0b5a273bb4520413c8b650, gid: 65cRt4uGMzo51AzXqptVsX" Jul 08 16:32:30 volumio1920x480 volumio[1383]: info: Getting Spotify volume Jul 08 16:32:30 volumio1920x480 volumio[1383]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 08 16:32:30 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetState Jul 08 16:32:30 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 5 Jul 08 16:32:30 volumio1920x480 volumio[1383]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30 Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: Preload queue cleared Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::ClearQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::clearPlayQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::saveQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::addQueueItems Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::addQueueItems Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: Preload queue cleared Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: Adding Item to queue: spotify:track:3w0eFAME3IxlonearUIaXJ Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: Using cached record of: spotify:track:3w0eFAME3IxlonearUIaXJ Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPushQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::saveQueue Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::updateTrackBlock Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrackBlock Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPlay Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index 0 Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index undefined Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: [1751985153288] ControllerSpotify::clearAddPlayTrack Jul 08 16:32:33 volumio1920x480 volumio[1383]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: Discovery: Getting this device information Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetState Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:40 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="received connection id: MjQ3NzljZDItOGNiOS00NTY1LTg0YmUtZDE5MjQxOGUzNTVhK2RlYWxlcit0Y3A6Ly8wYWIxNTE0MS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQzUwNEU5RkU3QkVCMzQwRDgwRjZEMThEMkVCOTY1QjZFNTM0QjVEQTdEMjgxQ0IzODE5NTM3NDgxQTdBOTkwQg==" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:65cRt4uGMzo51AzXqptVsX: failed retrieving audio key: context deadline exceeded" Jul 08 16:32:42 volumio1920x480 volumio[1383]: info: Spotify volume: 100 Jul 08 16:32:42 volumio1920x480 volumio[1383]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="resolved context of track" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:32:42 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:42+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:32:42 volumio1920x480 volumio[1383]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3w0eFAME3IxlonearUIaXJ","play_origin":"go-librespot"}} Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=debug msg="selected format OGG_VORBIS_320 (70d7aa318b4c0df2c0c9297c8aec784bab307c28)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=debug msg="requested aes key for file 70d7aa318b4c0df2c0c9297c8aec784bab307c28, gid: 3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=debug msg="fetched first chunk of 15, total size is 7466563 bytes" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=debug msg="created new output device" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: time="2025-07-08T16:32:43+02:00" level=info msg="loaded track \"Ewo\" (paused: false, position: 0ms, duration: 180765ms, prefetched: false)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:43 volumio1920x480 go-librespot[4193]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:32:43 volumio1920x480 go-librespot[4192]: Aborted Jul 08 16:32:43 volumio1920x480 volumio[1383]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:32:43 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:32:43 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:32:43 volumio1920x480 volumio[1383]: info: Connection to go-librespot Websocket closed Jul 08 16:32:46 volumio1920x480 volumio[1383]: info: Initializing connection to go-librespot Websocket Jul 08 16:32:46 volumio1920x480 volumio[1383]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:32:46 volumio1920x480 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jul 08 16:32:46 volumio1920x480 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:32:46 volumio1920x480 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 16:32:46 volumio1920x480 go-librespot[4232]: go-librespot daemon starting... Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=debug msg="app state loaded" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02: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]" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=info msg="zeroconf server listening on port 36635" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=debug msg="obtained new client token: AAAIVfdObk4Tgp33N+qXay0XqDL9U2mIRhnPhCT3OKCCgug9Kyr7OowcA5+30/PmQyuJ21HtVoZiGe4bOprmrvbJIp7KaTYU4bfLSKsz9VbmmlcPgsGyepvYzjPsXhesyZzva8TSg9XZFGlTHRS1vx6s4yI1cRAw1L1hvgyg3aXPFIqEZJDhGyFc6+TY0ttAj4wCoBlozCLos16AUxcAtpQYb69PZ+mHeZZ4ZEpry/sM6pBKQnP9IAUqiA==" Jul 08 16:32:46 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:46+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="completed keyexchange" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="completed challenge" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=info msg="authenticated AP as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=info msg="authenticated Login5 as 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="initializing zeroconf session, username: 31rpeznnia6zthzdlzxkalygovbe" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="dealer connection opened" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=trace msg="starting dealer recv loop" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=trace msg="received accesspoint ping" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="received connection id: YTMyODJhOTMtMjBiMy00MjI2LTg2NDMtOWE4ZWU0NDU2NWQ3K2RlYWxlcit0Y3A6Ly8wYWIxNTE3Yi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDk4MjdFQTgwRDIwQTkwRUU3RThBMDkxQzIwOTBCNkFENEFCMzUyMDE3QkM3NzZGNDZGQUI4OTBGQUQzNTQ3Mg==" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=trace msg="received accesspoint pong ack" Jul 08 16:32:47 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:47+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioPlay Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index 0 Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::stop Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::play index undefined Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreStateMachine::startPlaybackTimer Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CorePlayQueue::getTrack 0 Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: [1751985169153] ControllerSpotify::clearAddPlayTrack Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: Sending Spotify command with payload to local API: /player/play Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="resolved context of track" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="selected format OGG_VORBIS_320 (70d7aa318b4c0df2c0c9297c8aec784bab307c28)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="requested aes key for file 70d7aa318b4c0df2c0c9297c8aec784bab307c28, gid: 3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: Initializing connection to go-librespot Websocket Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="new websocket client" Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: Connection to go-librespot Websocket established Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="fetched first chunk of 15, total size is 7466563 bytes" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="created new output device" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: time="2025-07-08T16:32:49+02:00" level=info msg="loaded track \"Ewo\" (paused: false, position: 0ms, duration: 180765ms, prefetched: false)" uri="spotify:track:3w0eFAME3IxlonearUIaXJ" Jul 08 16:32:49 volumio1920x480 go-librespot[4233]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 16:32:49 volumio1920x480 go-librespot[4232]: Aborted Jul 08 16:32:49 volumio1920x480 volumio[1383]: info: Connection to go-librespot Websocket closed Jul 08 16:32:49 volumio1920x480 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 16:32:49 volumio1920x480 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 16:32:49 volumio1920x480 volumio[1383]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 16:32:51 volumio1920x480 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 16:32:52 volumio1920x480 volumio[1383]: info: Getting Spotify volume Jul 08 16:32:52 volumio1920x480 volumio[1383]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 16:32:52 volumio1920x480 volumio[1383]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 16:32:52 volumio1920x480 volumio[1383]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jul 08 16:32:52 volumio1920x480 volumio[1383]: errno: -111, Jul 08 16:32:52 volumio1920x480 volumio[1383]: code: 'ECONNREFUSED', Jul 08 16:32:52 volumio1920x480 volumio[1383]: syscall: 'connect', Jul 08 16:32:52 volumio1920x480 volumio[1383]: address: '127.0.0.1', Jul 08 16:32:52 volumio1920x480 volumio[1383]: port: 9879, Jul 08 16:32:52 volumio1920x480 volumio[1383]: response: undefined Jul 08 16:32:52 volumio1920x480 volumio[1383]: } Jul 08 16:32:52 volumio1920x480 volumio[1383]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 16:32:52 volumio1920x480 sudo[4272]: volumio : unable to resolve host volumio1920x480: System error Jul 08 16:32:52 volumio1920x480 sudo[4272]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-08 16:31' Jul 08 16:32:52 volumio1920x480 sudo[4272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="4f980d5cf693b4272997a2fa2da8bb8036ddf1ab" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jul 5 02:50:33 UTC 2025" VOLUMIO_VERSION="4.015" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d42ab79cc13d24482826e04fda2e8350"