May 29 11:21:01 testing volumio[1281]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 29 11:21:01 testing volumio[1281]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 29 11:21:01 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 11:21:01 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 11:21:01 testing volumio[1281]: info: Starting MyVolumio Remote Streaming Endpoints May 29 11:21:01 testing volumio[1281]: info: MyVolumio not started May 29 11:21:01 testing volumio[1281]: info: Initializing device activation check May 29 11:21:01 testing volumio[1281]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 29 11:21:01 testing volumio[1281]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 29 11:21:04 testing volumio[1281]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 29 11:21:04 testing volumio[1281]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 29 11:21:04 testing volumio[1281]: info: Streaming services startup May 29 11:21:04 testing volumio[1281]: info: Starting Streaming Daemon May 29 11:21:05 testing sudo[1615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 29 11:21:05 testing sudo[1615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:05 testing volumio[1281]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 29 11:21:05 testing sudo[1615]: pam_unix(sudo:session): session closed for user root May 29 11:21:05 testing volumio[1281]: error: Cannot start Volumio Streaming Daemon May 29 11:21:05 testing volumio[1281]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 29 11:21:05 testing volumio[1281]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 29 11:21:08 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 11:21:08 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 11:21:08 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:21:08 testing volumio-remote-updater[572]: No test mode May 29 11:21:08 testing volumio-remote-updater[572]: Alpha test mode enabled May 29 11:21:08 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 29 11:21:08 testing volumio[1281]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

NEW ADDITIONS

\n\n

FIXES

\n\n","title":"Update v4.004","updateavailable":true} May 29 11:21:09 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 11:21:10 testing sudo[1630]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 11:21:10 testing sudo[1630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:10 testing sudo[1630]: pam_unix(sudo:session): session closed for user root May 29 11:21:10 testing sudo[1632]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 11:21:10 testing sudo[1632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:11 testing sudo[1632]: pam_unix(sudo:session): session closed for user root May 29 11:21:11 testing volumio[1281]: verbose: New Socket.io Connection to 192.168.1.104 from 192.168.1.7 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::volumioGetVisibleSources May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:11 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 11:21:11 testing volumio[1281]: info: Received Get System Info May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:11 testing systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 11:21:11 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:11 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:11 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:11 testing volumio[1281]: info: Listing playlists May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 11:21:11 testing dbus-daemon[561]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.24' (uid=0 pid=1636 comm="timedatectl show --property=NTPSynchronized --valu") May 29 11:21:11 testing systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 29 11:21:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 11:21:12 testing dbus-daemon[561]: [system] Successfully activated service 'org.freedesktop.timedate1' May 29 11:21:12 testing systemd[1]: Started systemd-timedated.service - Time & Date Service. May 29 11:21:12 testing setdatetime-helper.sh[1635]: Time is not synchronized. Attempting to sync... May 29 11:21:12 testing sudo[1654]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 15:21:12 GMT#015' May 29 11:21:12 testing sudo[1654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 11:21:12 testing setdatetime-helper.sh[1659]: Thu May 29 11:21:12 EDT 2025 May 29 11:21:12 testing systemd-journald[330]: Time jumped backwards, rotating. May 29 11:21:12 testing systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 11:21:12 testing setdatetime-helper.sh[1635]: Time synchronized successfully. May 29 11:21:12 testing sudo[1654]: pam_unix(sudo:session): session closed for user root May 29 11:21:12 testing systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 11:21:12 testing sudo[1663]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 11:21:12 testing sudo[1665]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 11:21:12 testing sudo[1665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:12 testing sudo[1663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:12 testing sudo[1665]: pam_unix(sudo:session): session closed for user root May 29 11:21:12 testing sudo[1663]: pam_unix(sudo:session): session closed for user root May 29 11:21:12 testing volumio[1281]: verbose: New Socket.io Connection to 192.168.1.106 from 192.168.1.7 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::volumioGetVisibleSources May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:12 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 11:21:12 testing volumio[1281]: info: Received Get System Info May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:12 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:12 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:12 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:12 testing volumio[1281]: info: Listing playlists May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 11:21:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 11:21:13 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:13 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 11:21:14 testing volumio[1281]: info: Received Get System Info May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:14 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:14 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:14 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 29 11:21:15 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 11:21:15 testing volumio[1281]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 29 11:21:16 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:16 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:16 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: wizard , setOnboardingWizardFalse May 29 11:21:17 testing volumio-remote-updater[572]: No test mode May 29 11:21:17 testing volumio-remote-updater[572]: Alpha test mode enabled May 29 11:21:17 testing volumio-remote-updater[572]: No test mode May 29 11:21:17 testing volumio-remote-updater[572]: Alpha test mode enabled May 29 11:21:17 testing volumio[1281]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

NEW ADDITIONS

\n\n

FIXES

\n\n","title":"Update v4.004","updateavailable":true} May 29 11:21:17 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 11:21:18 testing volumio-remote-updater[572]: No test mode May 29 11:21:18 testing volumio-remote-updater[572]: Alpha test mode enabled May 29 11:21:18 testing volumio-remote-updater[572]: No test mode May 29 11:21:18 testing volumio-remote-updater[572]: Alpha test mode enabled May 29 11:21:18 testing volumio[1281]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

NEW ADDITIONS

\n\n

FIXES

\n\n","title":"Update v4.004","updateavailable":true} May 29 11:21:18 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 11:21:18 testing volumio[1281]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

NEW ADDITIONS

\n\n

FIXES

\n\n","title":"Update v4.004","updateavailable":true} May 29 11:21:18 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 11:21:18 testing volumio[1281]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

NEW ADDITIONS

\n\n

FIXES

\n\n","title":"Update v4.004","updateavailable":true} May 29 11:21:18 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::volumioGetBrowseSources May 29 11:21:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 11:21:21 testing volumio[1281]: info: Update: [object Object] May 29 11:21:21 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , checkSystemIntegrity May 29 11:21:21 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 11:21:22 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 11:21:23 testing volumio[1281]: info: CoreCommandRouter::Close All Modals sent May 29 11:21:23 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , setTOSAccepted May 29 11:21:24 testing volumio[1281]: error: MyVolumio Plugin failed to authenticate in a timely fashion May 29 11:21:24 testing volumio[1281]: info: Completed starting MyVolumio Plugin May 29 11:21:24 testing volumio[1281]: [Metrics] CommandRouter: 58s 205.66ms May 29 11:21:24 testing volumio[1281]: info: CoreCommandRouter::volumiosetStartupVolume May 29 11:21:24 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 11:21:24 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 11:21:24 testing volumio[1281]: info: CoreCommandRouter::Close All Modals sent May 29 11:21:24 testing volumio[1281]: info: CoreCommandRouter::Close All Modals sent May 29 11:21:25 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable May 29 11:21:25 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 29 11:21:25 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 11:21:30 testing volumio[1281]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 29 11:21:30 testing volumio[1281]: info: Received Get System Version May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 11:21:30 testing volumio[1281]: info: Received Get System Info May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:30 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:30 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:31 testing volumio[1281]: info: BOOT COMPLETED May 29 11:21:41 testing systemd[1]: systemd-timedated.service: Deactivated successfully. May 29 11:21:54 testing sudo[1749]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 11:21:54 testing sudo[1749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:54 testing sudo[1751]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 11:21:54 testing sudo[1749]: pam_unix(sudo:session): session closed for user root May 29 11:21:54 testing sudo[1751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:21:54 testing sudo[1751]: pam_unix(sudo:session): session closed for user root May 29 11:21:55 testing volumio[1281]: verbose: New Socket.io Connection to 192.168.1.104 from 192.168.1.7 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: Received Get System Info May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:55 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetVisibleSources May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 11:21:55 testing volumio[1281]: info: Received Get System Info May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:21:55 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:21:55 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:21:55 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:21:55 testing volumio[1281]: info: Listing playlists May 29 11:21:56 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 11:21:59 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , setTestSystem May 29 11:21:59 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , checkUpdates May 29 11:21:59 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:21:59 testing volumio-remote-updater[572]: PROGRESS: 0, STATUS: "Starting update", ETA: "6m" May 29 11:21:59 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , notifyProgress May 29 11:21:59 testing volumio-remote-updater[1755]: /bin/rm: cannot remove '/imgpart/rck*': No such file or directory May 29 11:21:59 testing volumio-remote-updater[1755]: /bin/rm: cannot remove '/imgpart/*.part': No such file or directory May 29 11:21:59 testing volumio-remote-updater[1755]: /bin/rm: cannot remove '/imgpart/*.zs-old': No such file or directory May 29 11:21:59 testing volumio-remote-updater[572]: PROGRESS: 5, STATUS: "Preparing update", ETA: "5m" May 29 11:22:00 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 29 11:22:00 testing volumio-remote-updater[572]: PROGRESS: 5, STATUS: "Preparing update", ETA: "5m" May 29 11:22:00 testing volumio-remote-updater[572]: PROGRESS: 5, STATUS: "Preparing update", ETA: "5m" May 29 11:22:00 testing volumio-remote-updater[572]: PROGRESS: 5, STATUS: "Preparing update", ETA: "5m" May 29 11:22:00 testing volumio[1281]: info: Killing processes that might interfere with OTA Updates May 29 11:22:00 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:00 testing volumio[1281]: updateProgress May 29 11:22:00 testing sudo[1775]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/killall matchbox-keyboard May 29 11:22:00 testing sudo[1775]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:22:00 testing sudo[1777]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/killall matchbox-window-manager May 29 11:22:00 testing sudo[1777]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:22:00 testing volumio[1281]: { May 29 11:22:00 testing volumio[1281]: downloadSpeed: '', May 29 11:22:00 testing volumio[1281]: eta: '5m', May 29 11:22:00 testing volumio[1281]: progress: 5, May 29 11:22:00 testing volumio[1281]: status: 'Preparing update' May 29 11:22:00 testing volumio[1281]: } May 29 11:22:00 testing sudo[1775]: pam_unix(sudo:session): session closed for user root May 29 11:22:00 testing volumio[1281]: error: Cannot kill process: Error: Command failed: /usr/bin/sudo /usr/bin/killall matchbox-keyboard May 29 11:22:00 testing volumio[1281]: matchbox-keyboard: no process found May 29 11:22:00 testing sudo[1777]: pam_unix(sudo:session): session closed for user root May 29 11:22:00 testing volumio[1281]: error: Cannot kill process: Error: Command failed: /usr/bin/sudo /usr/bin/killall matchbox-window-manager May 29 11:22:00 testing volumio[1281]: matchbox-window-manager: no process found May 29 11:22:02 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:02 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:02 testing volumio[1281]: updateProgress May 29 11:22:02 testing volumio[1281]: { May 29 11:22:02 testing volumio[1281]: downloadSpeed: '', May 29 11:22:02 testing volumio[1281]: eta: '5m', May 29 11:22:02 testing volumio[1281]: progress: 10, May 29 11:22:02 testing volumio[1281]: status: 'Creating backup' May 29 11:22:02 testing volumio[1281]: } May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:03 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:03 testing volumio[1281]: updateProgress May 29 11:22:03 testing volumio[1281]: { May 29 11:22:03 testing volumio[1281]: downloadSpeed: '', May 29 11:22:03 testing volumio[1281]: eta: '5m', May 29 11:22:03 testing volumio[1281]: progress: 10, May 29 11:22:03 testing volumio[1281]: status: 'Creating backup' May 29 11:22:03 testing volumio[1281]: } May 29 11:22:04 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:04 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:04 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:04 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:04 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:04 testing volumio[1281]: updateProgress May 29 11:22:04 testing volumio[1281]: { May 29 11:22:04 testing volumio[1281]: downloadSpeed: '', May 29 11:22:04 testing volumio[1281]: eta: '5m', May 29 11:22:04 testing volumio[1281]: progress: 10, May 29 11:22:04 testing volumio[1281]: status: 'Creating backup' May 29 11:22:04 testing volumio[1281]: } May 29 11:22:04 testing upmpdcli[1804]: writing RSA key May 29 11:22:05 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 11:22:05 testing volumio-remote-updater[572]: PROGRESS: 10, STATUS: "Creating backup", ETA: "5m" May 29 11:22:05 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:05 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:05 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:05 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:05 testing volumio[1281]: updateProgress May 29 11:22:05 testing volumio[1281]: { May 29 11:22:05 testing volumio[1281]: downloadSpeed: '', May 29 11:22:05 testing volumio[1281]: eta: '5m', May 29 11:22:05 testing volumio[1281]: progress: 11, May 29 11:22:05 testing volumio[1281]: status: 'Creating backup' May 29 11:22:05 testing volumio[1281]: } May 29 11:22:07 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:07 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:07 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:07 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:07 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:07 testing volumio[1281]: updateProgress May 29 11:22:07 testing volumio[1281]: { May 29 11:22:07 testing volumio[1281]: downloadSpeed: '', May 29 11:22:07 testing volumio[1281]: eta: '5m', May 29 11:22:07 testing volumio[1281]: progress: 11, May 29 11:22:07 testing volumio[1281]: status: 'Creating backup' May 29 11:22:07 testing volumio[1281]: } May 29 11:22:08 testing volumio-remote-updater[572]: PROGRESS: 11, STATUS: "Creating backup", ETA: "5m" May 29 11:22:08 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:08 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:08 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:08 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:08 testing volumio[1281]: updateProgress May 29 11:22:08 testing volumio[1281]: { May 29 11:22:08 testing volumio[1281]: downloadSpeed: '', May 29 11:22:08 testing volumio[1281]: eta: '5m', May 29 11:22:08 testing volumio[1281]: progress: 12, May 29 11:22:08 testing volumio[1281]: status: 'Creating backup' May 29 11:22:08 testing volumio[1281]: } May 29 11:22:09 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:09 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:09 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:09 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:10 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:10 testing volumio[1281]: updateProgress May 29 11:22:10 testing volumio[1281]: { May 29 11:22:10 testing volumio[1281]: downloadSpeed: '', May 29 11:22:10 testing volumio[1281]: eta: '5m', May 29 11:22:10 testing volumio[1281]: progress: 12, May 29 11:22:10 testing volumio[1281]: status: 'Creating backup' May 29 11:22:10 testing volumio[1281]: } May 29 11:22:11 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:11 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:11 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:11 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:11 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:11 testing volumio[1281]: updateProgress May 29 11:22:11 testing volumio[1281]: { May 29 11:22:11 testing volumio[1281]: downloadSpeed: '', May 29 11:22:11 testing volumio[1281]: eta: '5m', May 29 11:22:11 testing volumio[1281]: progress: 12, May 29 11:22:11 testing volumio[1281]: status: 'Creating backup' May 29 11:22:11 testing volumio[1281]: } May 29 11:22:12 testing volumio-remote-updater[572]: PROGRESS: 12, STATUS: "Creating backup", ETA: "5m" May 29 11:22:12 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:12 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:12 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:12 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:12 testing volumio[1281]: updateProgress May 29 11:22:12 testing volumio[1281]: { May 29 11:22:12 testing volumio[1281]: downloadSpeed: '', May 29 11:22:12 testing volumio[1281]: eta: '5m', May 29 11:22:12 testing volumio[1281]: progress: 13, May 29 11:22:12 testing volumio[1281]: status: 'Creating backup' May 29 11:22:12 testing volumio[1281]: } May 29 11:22:13 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:13 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:13 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:13 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:13 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:13 testing volumio[1281]: updateProgress May 29 11:22:13 testing volumio[1281]: { May 29 11:22:13 testing volumio[1281]: downloadSpeed: '', May 29 11:22:13 testing volumio[1281]: eta: '5m', May 29 11:22:13 testing volumio[1281]: progress: 13, May 29 11:22:13 testing volumio[1281]: status: 'Creating backup' May 29 11:22:13 testing volumio[1281]: } May 29 11:22:13 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:13 testing volumio[1281]: updateProgress May 29 11:22:13 testing volumio[1281]: { May 29 11:22:13 testing volumio[1281]: downloadSpeed: '', May 29 11:22:13 testing volumio[1281]: eta: '5m', May 29 11:22:13 testing volumio[1281]: progress: 13, May 29 11:22:13 testing volumio[1281]: status: 'Creating backup' May 29 11:22:13 testing volumio[1281]: } May 29 11:22:15 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:15 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:15 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:15 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:15 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:15 testing volumio[1281]: updateProgress May 29 11:22:15 testing volumio[1281]: { May 29 11:22:15 testing volumio[1281]: downloadSpeed: '', May 29 11:22:15 testing volumio[1281]: eta: '5m', May 29 11:22:15 testing volumio[1281]: progress: 13, May 29 11:22:15 testing volumio[1281]: status: 'Creating backup' May 29 11:22:15 testing volumio[1281]: } May 29 11:22:16 testing volumio-remote-updater[572]: PROGRESS: 13, STATUS: "Creating backup", ETA: "5m" May 29 11:22:16 testing volumio-remote-updater[572]: PROGRESS: 14, STATUS: "Creating backup", ETA: "5m" May 29 11:22:16 testing volumio-remote-updater[572]: PROGRESS: 14, STATUS: "Creating backup", ETA: "5m" May 29 11:22:16 testing volumio-remote-updater[572]: PROGRESS: 14, STATUS: "Creating backup", ETA: "5m" May 29 11:22:16 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:16 testing volumio[1281]: updateProgress May 29 11:22:16 testing volumio[1281]: { May 29 11:22:16 testing volumio[1281]: downloadSpeed: '', May 29 11:22:16 testing volumio[1281]: eta: '5m', May 29 11:22:16 testing volumio[1281]: progress: 14, May 29 11:22:16 testing volumio[1281]: status: 'Creating backup' May 29 11:22:16 testing volumio[1281]: } May 29 11:22:17 testing volumio-remote-updater[572]: PROGRESS: 14, STATUS: "Creating backup", ETA: "5m" May 29 11:22:17 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:17 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:17 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:17 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:17 testing volumio[1281]: updateProgress May 29 11:22:17 testing volumio[1281]: { May 29 11:22:17 testing volumio[1281]: downloadSpeed: '', May 29 11:22:17 testing volumio[1281]: eta: '5m', May 29 11:22:17 testing volumio[1281]: progress: 15, May 29 11:22:17 testing volumio[1281]: status: 'Creating backup' May 29 11:22:17 testing volumio[1281]: } May 29 11:22:19 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:19 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:19 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:19 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:19 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:19 testing volumio[1281]: updateProgress May 29 11:22:19 testing volumio[1281]: { May 29 11:22:19 testing volumio[1281]: downloadSpeed: '', May 29 11:22:19 testing volumio[1281]: eta: '5m', May 29 11:22:19 testing volumio[1281]: progress: 15, May 29 11:22:19 testing volumio[1281]: status: 'Creating backup' May 29 11:22:19 testing volumio[1281]: } May 29 11:22:20 testing volumio-remote-updater[572]: PROGRESS: 15, STATUS: "Creating backup", ETA: "5m" May 29 11:22:20 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:20 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:20 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:20 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:20 testing volumio[1281]: updateProgress May 29 11:22:20 testing volumio[1281]: { May 29 11:22:20 testing volumio[1281]: downloadSpeed: '', May 29 11:22:20 testing volumio[1281]: eta: '5m', May 29 11:22:20 testing volumio[1281]: progress: 16, May 29 11:22:20 testing volumio[1281]: status: 'Creating backup' May 29 11:22:20 testing volumio[1281]: } May 29 11:22:21 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:21 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:21 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:21 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:21 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:21 testing volumio[1281]: updateProgress May 29 11:22:21 testing volumio[1281]: { May 29 11:22:21 testing volumio[1281]: downloadSpeed: '', May 29 11:22:21 testing volumio[1281]: eta: '5m', May 29 11:22:21 testing volumio[1281]: progress: 16, May 29 11:22:21 testing volumio[1281]: status: 'Creating backup' May 29 11:22:21 testing volumio[1281]: } May 29 11:22:23 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:23 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:23 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:23 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:23 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:23 testing volumio[1281]: updateProgress May 29 11:22:23 testing volumio[1281]: { May 29 11:22:23 testing volumio[1281]: downloadSpeed: '', May 29 11:22:23 testing volumio[1281]: eta: '5m', May 29 11:22:23 testing volumio[1281]: progress: 16, May 29 11:22:23 testing volumio[1281]: status: 'Creating backup' May 29 11:22:23 testing volumio[1281]: } May 29 11:22:24 testing volumio-remote-updater[572]: PROGRESS: 16, STATUS: "Creating backup", ETA: "5m" May 29 11:22:24 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:24 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:24 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:24 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:24 testing volumio[1281]: updateProgress May 29 11:22:24 testing volumio[1281]: { May 29 11:22:24 testing volumio[1281]: downloadSpeed: '', May 29 11:22:24 testing volumio[1281]: eta: '5m', May 29 11:22:24 testing volumio[1281]: progress: 17, May 29 11:22:24 testing volumio[1281]: status: 'Creating backup' May 29 11:22:24 testing volumio[1281]: } May 29 11:22:26 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:26 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:26 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:26 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:26 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:26 testing volumio[1281]: updateProgress May 29 11:22:26 testing volumio[1281]: { May 29 11:22:26 testing volumio[1281]: downloadSpeed: '', May 29 11:22:26 testing volumio[1281]: eta: '5m', May 29 11:22:26 testing volumio[1281]: progress: 17, May 29 11:22:26 testing volumio[1281]: status: 'Creating backup' May 29 11:22:26 testing volumio[1281]: } May 29 11:22:28 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:28 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:28 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:28 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:28 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:28 testing volumio[1281]: updateProgress May 29 11:22:28 testing volumio[1281]: { May 29 11:22:28 testing volumio[1281]: downloadSpeed: '', May 29 11:22:28 testing volumio[1281]: eta: '5m', May 29 11:22:28 testing volumio[1281]: progress: 17, May 29 11:22:28 testing volumio[1281]: status: 'Creating backup' May 29 11:22:28 testing volumio[1281]: } May 29 11:22:29 testing volumio-remote-updater[572]: PROGRESS: 17, STATUS: "Creating backup", ETA: "5m" May 29 11:22:29 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:29 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:29 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:29 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:29 testing volumio[1281]: updateProgress May 29 11:22:29 testing volumio[1281]: { May 29 11:22:29 testing volumio[1281]: downloadSpeed: '', May 29 11:22:29 testing volumio[1281]: eta: '5m', May 29 11:22:29 testing volumio[1281]: progress: 18, May 29 11:22:29 testing volumio[1281]: status: 'Creating backup' May 29 11:22:29 testing volumio[1281]: } May 29 11:22:30 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:30 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:30 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:30 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:30 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:30 testing volumio[1281]: updateProgress May 29 11:22:30 testing volumio[1281]: { May 29 11:22:30 testing volumio[1281]: downloadSpeed: '', May 29 11:22:30 testing volumio[1281]: eta: '5m', May 29 11:22:30 testing volumio[1281]: progress: 18, May 29 11:22:30 testing volumio[1281]: status: 'Creating backup' May 29 11:22:30 testing volumio[1281]: } May 29 11:22:32 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:32 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:32 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:32 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:32 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:32 testing volumio[1281]: updateProgress May 29 11:22:32 testing volumio[1281]: { May 29 11:22:32 testing volumio[1281]: downloadSpeed: '', May 29 11:22:32 testing volumio[1281]: eta: '5m', May 29 11:22:32 testing volumio[1281]: progress: 18, May 29 11:22:32 testing volumio[1281]: status: 'Creating backup' May 29 11:22:32 testing volumio[1281]: } May 29 11:22:33 testing volumio-remote-updater[572]: PROGRESS: 18, STATUS: "Creating backup", ETA: "5m" May 29 11:22:33 testing volumio-remote-updater[572]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" May 29 11:22:33 testing volumio-remote-updater[572]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" May 29 11:22:33 testing volumio-remote-updater[572]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" May 29 11:22:33 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:33 testing volumio[1281]: updateProgress May 29 11:22:33 testing volumio[1281]: { May 29 11:22:33 testing volumio[1281]: downloadSpeed: '', May 29 11:22:33 testing volumio[1281]: eta: '5m', May 29 11:22:33 testing volumio[1281]: progress: 19, May 29 11:22:33 testing volumio[1281]: status: 'Creating backup' May 29 11:22:33 testing volumio[1281]: } May 29 11:22:34 testing volumio-remote-updater[572]: PROGRESS: 19, STATUS: "Creating backup", ETA: "5m" May 29 11:22:34 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:34 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:34 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:34 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:34 testing volumio[1281]: updateProgress May 29 11:22:34 testing volumio[1281]: { May 29 11:22:34 testing volumio[1281]: downloadSpeed: '', May 29 11:22:34 testing volumio[1281]: eta: '5m', May 29 11:22:34 testing volumio[1281]: progress: 20, May 29 11:22:34 testing volumio[1281]: status: 'Creating backup' May 29 11:22:34 testing volumio[1281]: } May 29 11:22:36 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:36 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:36 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:36 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:36 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:36 testing volumio[1281]: updateProgress May 29 11:22:36 testing volumio[1281]: { May 29 11:22:36 testing volumio[1281]: downloadSpeed: '', May 29 11:22:36 testing volumio[1281]: eta: '5m', May 29 11:22:36 testing volumio[1281]: progress: 20, May 29 11:22:36 testing volumio[1281]: status: 'Creating backup' May 29 11:22:36 testing volumio[1281]: } May 29 11:22:37 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:37 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:37 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:37 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:37 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:37 testing volumio[1281]: updateProgress May 29 11:22:37 testing volumio[1281]: { May 29 11:22:37 testing volumio[1281]: downloadSpeed: '', May 29 11:22:37 testing volumio[1281]: eta: '5m', May 29 11:22:37 testing volumio[1281]: progress: 20, May 29 11:22:37 testing volumio[1281]: status: 'Creating backup' May 29 11:22:37 testing volumio[1281]: } May 29 11:22:38 testing volumio-remote-updater[572]: PROGRESS: 20, STATUS: "Creating backup", ETA: "5m" May 29 11:22:38 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:38 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:38 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:38 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:38 testing volumio[1281]: updateProgress May 29 11:22:38 testing volumio[1281]: { May 29 11:22:38 testing volumio[1281]: downloadSpeed: '', May 29 11:22:38 testing volumio[1281]: eta: '5m', May 29 11:22:38 testing volumio[1281]: progress: 21, May 29 11:22:38 testing volumio[1281]: status: 'Creating backup' May 29 11:22:38 testing volumio[1281]: } May 29 11:22:40 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:40 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:40 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:40 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:40 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:40 testing volumio[1281]: updateProgress May 29 11:22:40 testing volumio[1281]: { May 29 11:22:40 testing volumio[1281]: downloadSpeed: '', May 29 11:22:40 testing volumio[1281]: eta: '5m', May 29 11:22:40 testing volumio[1281]: progress: 21, May 29 11:22:40 testing volumio[1281]: status: 'Creating backup' May 29 11:22:40 testing volumio[1281]: } May 29 11:22:41 testing volumio-remote-updater[572]: PROGRESS: 21, STATUS: "Creating backup", ETA: "5m" May 29 11:22:41 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:41 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:41 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:41 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:41 testing volumio[1281]: updateProgress May 29 11:22:41 testing volumio[1281]: { May 29 11:22:41 testing volumio[1281]: downloadSpeed: '', May 29 11:22:41 testing volumio[1281]: eta: '5m', May 29 11:22:41 testing volumio[1281]: progress: 22, May 29 11:22:41 testing volumio[1281]: status: 'Creating backup' May 29 11:22:41 testing volumio[1281]: } May 29 11:22:42 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:42 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:42 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:42 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:42 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:42 testing volumio[1281]: updateProgress May 29 11:22:42 testing volumio[1281]: { May 29 11:22:42 testing volumio[1281]: downloadSpeed: '', May 29 11:22:42 testing volumio[1281]: eta: '5m', May 29 11:22:42 testing volumio[1281]: progress: 22, May 29 11:22:42 testing volumio[1281]: status: 'Creating backup' May 29 11:22:42 testing volumio[1281]: } May 29 11:22:43 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 29 11:22:43 testing volumio[1281]: info: MyVolumio login type: Token May 29 11:22:44 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:44 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:44 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:44 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:44 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:44 testing volumio[1281]: updateProgress May 29 11:22:44 testing volumio[1281]: { May 29 11:22:44 testing volumio[1281]: downloadSpeed: '', May 29 11:22:44 testing volumio[1281]: eta: '5m', May 29 11:22:44 testing volumio[1281]: progress: 22, May 29 11:22:44 testing volumio[1281]: status: 'Creating backup' May 29 11:22:44 testing volumio[1281]: } May 29 11:22:45 testing volumio-remote-updater[572]: PROGRESS: 22, STATUS: "Creating backup", ETA: "5m" May 29 11:22:45 testing volumio-remote-updater[572]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" May 29 11:22:45 testing volumio-remote-updater[572]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" May 29 11:22:45 testing volumio-remote-updater[572]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" May 29 11:22:45 testing volumio[1281]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 29 11:22:45 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:45 testing volumio[1281]: updateProgress May 29 11:22:45 testing volumio[1281]: { May 29 11:22:45 testing volumio[1281]: downloadSpeed: '', May 29 11:22:45 testing volumio[1281]: eta: '5m', May 29 11:22:45 testing volumio[1281]: progress: 23, May 29 11:22:45 testing volumio[1281]: status: 'Creating backup' May 29 11:22:45 testing volumio[1281]: } May 29 11:22:46 testing volumio-remote-updater[572]: PROGRESS: 23, STATUS: "Creating backup", ETA: "5m" May 29 11:22:46 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:46 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:46 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:46 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:46 testing volumio[1281]: updateProgress May 29 11:22:46 testing volumio[1281]: { May 29 11:22:46 testing volumio[1281]: downloadSpeed: '', May 29 11:22:46 testing volumio[1281]: eta: '5m', May 29 11:22:46 testing volumio[1281]: progress: 24, May 29 11:22:46 testing volumio[1281]: status: 'Creating backup' May 29 11:22:46 testing volumio[1281]: } May 29 11:22:50 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:50 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:50 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:50 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:50 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:50 testing volumio[1281]: updateProgress May 29 11:22:50 testing volumio[1281]: { May 29 11:22:50 testing volumio[1281]: downloadSpeed: '', May 29 11:22:50 testing volumio[1281]: eta: '5m', May 29 11:22:50 testing volumio[1281]: progress: 24, May 29 11:22:50 testing volumio[1281]: status: 'Creating backup' May 29 11:22:50 testing volumio[1281]: } May 29 11:22:50 testing sudo[1868]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 11:22:50 testing sudo[1868]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:22:50 testing sudo[1870]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 11:22:50 testing sudo[1870]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:22:50 testing sudo[1868]: pam_unix(sudo:session): session closed for user root May 29 11:22:50 testing sudo[1870]: pam_unix(sudo:session): session closed for user root May 29 11:22:50 testing volumio[1281]: verbose: New Socket.io Connection to 192.168.1.104 from 192.168.1.7 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/129.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 May 29 11:22:50 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:50 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: Received Get System Info May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:22:51 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 24, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetVisibleSources May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 29 11:22:51 testing volumio[1281]: info: Received Get System Info May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:22:51 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: Listing playlists May 29 11:22:51 testing volumio[1281]: info: Received Get System Info May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 11:22:51 testing volumio[1281]: info: Discovery: Getting this device information May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:51 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 29 11:22:51 testing volumio[1281]: info: MyVolumio token set successfully May 29 11:22:51 testing volumio[1281]: info: MYVOLUMIO: Adding device May 29 11:22:51 testing volumio[1281]: info: MYVOLUMIO: Evaluating Server May 29 11:22:51 testing systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 11:22:51 testing volumio[1281]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage May 29 11:22:51 testing volumio[1281]: updateProgress May 29 11:22:51 testing volumio[1281]: { May 29 11:22:51 testing volumio[1281]: downloadSpeed: '', May 29 11:22:51 testing volumio[1281]: eta: '5m', May 29 11:22:51 testing volumio[1281]: progress: 25, May 29 11:22:51 testing volumio[1281]: status: 'Creating backup' May 29 11:22:51 testing volumio[1281]: } May 29 11:22:51 testing dbus-daemon[561]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.26' (uid=0 pid=1882 comm="timedatectl show --property=NTPSynchronized --valu") May 29 11:22:51 testing systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 29 11:22:52 testing dbus-daemon[561]: [system] Successfully activated service 'org.freedesktop.timedate1' May 29 11:22:52 testing systemd[1]: Started systemd-timedated.service - Time & Date Service. May 29 11:22:52 testing setdatetime-helper.sh[1881]: Time is not synchronized. Attempting to sync... May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 25, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing sudo[1905]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 15:22:52 GMT#015' May 29 11:22:52 testing sudo[1905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 11:22:52 testing setdatetime-helper.sh[1906]: Thu May 29 11:22:52 EDT 2025 May 29 11:22:52 testing systemd-journald[330]: Time jumped backwards, rotating. May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:52 testing sudo[1905]: pam_unix(sudo:session): session closed for user root May 29 11:22:52 testing setdatetime-helper.sh[1881]: Time synchronized successfully. May 29 11:22:52 testing systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 11:22:52 testing systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 11:22:52 testing volumio[1281]: info: MyVolumio Plan changed: premium May 29 11:22:52 testing volumio[1281]: info: [MyVolumio PluginManager] Subscribed plan changed to premium May 29 11:22:52 testing volumio[1281]: info: Removing browser output: myVolumio user plan is not superstar May 29 11:22:52 testing volumio[1281]: info: Removing audio output: May 29 11:22:52 testing volumio[1281]: info: MYVOLUMIO: Adding device May 29 11:22:52 testing volumio[1281]: info: MYVOLUMIO: Evaluating Server May 29 11:22:52 testing volumio[1281]: info: CoreCommandRouter::volumioGetState May 29 11:22:52 testing volumio[1281]: info: CorePlayQueue::getTrack 0 May 29 11:22:52 testing volumio[1281]: error: Failed to ping endpoint as1.myvolumio.org : unknown error May 29 11:22:52 testing volumio[1281]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 11:22:52 testing volumio[1281]: Error: Unable to resolve or reject the same promise twice May 29 11:22:52 testing volumio[1281]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) May 29 11:22:52 testing volumio[1281]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32371) May 29 11:22:52 testing volumio[1281]: at Socket.emit (node:events:514:28) May 29 11:22:52 testing volumio[1281]: at addChunk (node:internal/streams/readable:343:12) May 29 11:22:52 testing volumio[1281]: at readableAddChunk (node:internal/streams/readable:316:9) May 29 11:22:52 testing volumio[1281]: at Readable.push (node:internal/streams/readable:253:10) May 29 11:22:52 testing volumio[1281]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) May 29 11:22:52 testing volumio[1281]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 11:22:54 testing volumio-remote-updater[572]: PROGRESS: 27, STATUS: "Creating backup", ETA: "5m" May 29 11:22:54 testing volumio-remote-updater[572]: PROGRESS: 28, STATUS: "Creating backup", ETA: "5m" May 29 11:22:54 testing volumio-remote-updater[572]: PROGRESS: 28, STATUS: "Creating backup", ETA: "5m" May 29 11:22:54 testing volumio-remote-updater[572]: PROGRESS: 28, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 28, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" May 29 11:22:55 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m" May 29 11:22:57 testing sudo[1955]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-29 11:21' May 29 11:22:57 testing sudo[1955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 11:22:57 testing volumio-remote-updater[1968]: /bin/cp: cannot stat '/imgpart/volumio_factory.sqsh': No such file or directory May 29 11:22:57 testing volumio-remote-updater[1972]: /bin/rm: cannot remove '/imgpart/volumio_factory.sqsh': No such file or directory May 29 11:22:57 testing volumio-remote-updater[572]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m" 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="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 08:02:06 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="76fa67e30b28261e1dc7c3a89e610b9e"