Sep 16 18:29:30 rotel systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Sep 16 18:29:30 rotel dbus-daemon[925]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.116' (uid=0 pid=15676 comm="timedatectl show --property=NTPSynchronized --valu") Sep 16 18:29:30 rotel systemd[1]: Starting systemd-timedated.service - Time & Date Service... Sep 16 18:29:30 rotel dbus-daemon[925]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 16 18:29:30 rotel systemd[1]: Started systemd-timedated.service - Time & Date Service. Sep 16 18:29:30 rotel setdatetime-helper.sh[15675]: Time is not synchronized. Attempting to sync... Sep 16 18:29:30 rotel sudo[15684]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 16 Sep 2025 16:29:30 GMT#015' Sep 16 18:29:30 rotel sudo[15684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 16 18:29:30 rotel setdatetime-helper.sh[15685]: Tue Sep 16 18:29:30 CEST 2025 Sep 16 18:29:30 rotel sudo[15684]: pam_unix(sudo:session): session closed for user root Sep 16 18:29:30 rotel setdatetime-helper.sh[15675]: Time synchronized successfully. Sep 16 18:29:30 rotel systemd-journald[396]: Time jumped backwards, rotating. Sep 16 18:29:30 rotel systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Sep 16 18:29:30 rotel systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Sep 16 18:29:47 rotel volumio[1856]: info: Sep 16 18:29:47 rotel volumio[1856]: ---------------------------- MPD announces system playlist update Sep 16 18:29:47 rotel volumio[1856]: info: Ignoring MPD Status Update Sep 16 18:29:47 rotel volumio[1856]: info: Sep 16 18:29:47 rotel volumio[1856]: ---------------------------- MPD announces state update: player Sep 16 18:29:47 rotel volumio[1856]: info: ControllerMpd::getState Sep 16 18:29:47 rotel volumio[1856]: verbose: ControllerMpd::sendMpdCommand status Sep 16 18:29:47 rotel volumio[1856]: info: ------------------------------ 1ms Sep 16 18:29:47 rotel volumio[1856]: info: sendMpdCommand status took 1 milliseconds Sep 16 18:29:47 rotel volumio[1856]: verbose: ControllerMpd::parseState Sep 16 18:29:47 rotel volumio[1856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 16 18:29:47 rotel volumio[1856]: info: sendMpdCommand playlistinfo took 0 milliseconds Sep 16 18:29:47 rotel volumio[1856]: verbose: ControllerMpd::parseTrackInfo Sep 16 18:29:47 rotel volumio[1856]: info: ControllerMpd::pushState Sep 16 18:29:47 rotel volumio[1856]: info: CoreCommandRouter::servicePushState Sep 16 18:29:47 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:29:47 rotel volumio[1856]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Sep 16 18:29:47 rotel volumio[1856]: info: ------------------------------ 1ms Sep 16 18:30:00 rotel systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 16 18:30:02 rotel volumio[1856]: info: [1758040202558] [80s80s] Pushing the next song state Madonna - Holiday and getting next track. Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: CoreCommandRouter::servicePushState Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is3-ssl.mzstatic.com/image/thumb/Music125/v4/6a/a7/ee/6aa7ee93-aacc-336e-8451-bb384e262a93/source/600x600bb.jpg","name":"Madonna - Holiday","title":"Holiday","artist":"80s80s Party","album":"","streaming":true,"disableUiControls":true,"duration":"227","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Sep 16 18:30:02 rotel volumio[1856]: verbose: CURRENT POSITION 0 Sep 16 18:30:02 rotel volumio[1856]: info: CoreStateMachine::syncState stateService play Sep 16 18:30:02 rotel volumio[1856]: info: CoreStateMachine::syncState currentStatus play Sep 16 18:30:02 rotel volumio[1856]: info: Received an update from plugin. extracting info from payload Sep 16 18:30:02 rotel volumio[1856]: info: CoreStateMachine::pushState Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: CoreCommandRouter::volumioPushState Sep 16 18:30:02 rotel volumio[1856]: info: MRS: Pushing multiroomSync output update for this device Sep 16 18:30:02 rotel volumio[1856]: info: MRS: Pushing multiroomSync output Sep 16 18:30:02 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: CoreStateMachine::pushState Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: CoreCommandRouter::volumioPushState Sep 16 18:30:02 rotel volumio[1856]: info: MRS: Pushing multiroomSync output update for this device Sep 16 18:30:02 rotel volumio[1856]: info: MRS: Pushing multiroomSync output Sep 16 18:30:02 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: [1758040202567] [80s80s] getContentOfUrl started with url http://iris-80s80s.loverad.io/flow.json?station=252&count=1 Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:02 rotel volumio[1856]: info: CorePlayQueue::getTrack 1 Sep 16 18:30:02 rotel volumio[1856]: info: [1758040202654] [80s80s] received new event containing 1 songs. Sep 16 18:30:02 rotel volumio[1856]: info: [1758040202655] [80s80s] PlayNextTrack API delay: 30 Sep 16 18:30:02 rotel volumio[1856]: info: [1758040202655] [80s80s] Setting timer to: 227000 milliseconds. Sep 16 18:30:03 rotel volumio[1856]: info: Sep 16 18:30:03 rotel volumio[1856]: ---------------------------- MPD announces system playlist update Sep 16 18:30:03 rotel volumio[1856]: info: Ignoring MPD Status Update Sep 16 18:30:03 rotel volumio[1856]: info: Sep 16 18:30:03 rotel volumio[1856]: ---------------------------- MPD announces state update: player Sep 16 18:30:03 rotel volumio[1856]: info: ControllerMpd::getState Sep 16 18:30:03 rotel volumio[1856]: verbose: ControllerMpd::sendMpdCommand status Sep 16 18:30:03 rotel volumio[1856]: info: ------------------------------ 1ms Sep 16 18:30:03 rotel volumio[1856]: info: sendMpdCommand status took 1 milliseconds Sep 16 18:30:03 rotel volumio[1856]: verbose: ControllerMpd::parseState Sep 16 18:30:03 rotel volumio[1856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 16 18:30:03 rotel volumio[1856]: info: sendMpdCommand playlistinfo took 0 milliseconds Sep 16 18:30:03 rotel volumio[1856]: verbose: ControllerMpd::parseTrackInfo Sep 16 18:30:03 rotel volumio[1856]: info: ControllerMpd::pushState Sep 16 18:30:03 rotel volumio[1856]: info: CoreCommandRouter::servicePushState Sep 16 18:30:03 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:03 rotel volumio[1856]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Sep 16 18:30:03 rotel volumio[1856]: info: ------------------------------ 1ms Sep 16 18:30:03 rotel sudo[16083]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 16 18:30:03 rotel sudo[16083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 18:30:03 rotel sudo[16085]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 16 18:30:03 rotel sudo[16085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 18:30:03 rotel sudo[16083]: pam_unix(sudo:session): session closed for user root Sep 16 18:30:03 rotel sudo[16085]: pam_unix(sudo:session): session closed for user root Sep 16 18:30:03 rotel volumio[1856]: verbose: New Socket.io Connection to 192.168.178.22 from 192.168.178.20 UA: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:142.0) Gecko/20100101 Firefox/142.0 Engine version: 3 Transport: polling Total Clients: 5 Sep 16 18:30:04 rotel sudo[16089]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 16 18:30:04 rotel sudo[16089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 18:30:04 rotel sudo[16091]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 16 18:30:04 rotel sudo[16091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 16 18:30:04 rotel sudo[16089]: pam_unix(sudo:session): session closed for user root Sep 16 18:30:04 rotel sudo[16091]: pam_unix(sudo:session): session closed for user root Sep 16 18:30:04 rotel volumio[1856]: verbose: New Socket.io Connection to 192.168.178.22 from 192.168.178.20 UA: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:142.0) Gecko/20100101 Firefox/142.0 Engine version: 3 Transport: polling Total Clients: 5 Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:04 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 16 18:30:04 rotel volumio[1856]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::volumioGetVisibleSources Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 16 18:30:04 rotel volumio[1856]: info: Listing playlists Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 16 18:30:04 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 18:30:06 rotel volumio[1856]: info: Received Get System Info Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 18:30:06 rotel volumio[1856]: info: Discovery: Getting this device information Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:06 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:06 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 18:30:07 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 18:30:07 rotel volumio[1856]: info: Received Get System Info Sep 16 18:30:07 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 18:30:07 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 18:30:07 rotel volumio[1856]: info: Discovery: Getting this device information Sep 16 18:30:07 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:07 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:07 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 18:30:10 rotel volumio[1856]: info: Enabling plugin now_playing Sep 16 18:30:10 rotel volumio[1856]: info: Loading plugin "now_playing"... Sep 16 18:30:10 rotel volumio[1856]: error: !!!! WARNING !!!! Sep 16 18:30:10 rotel volumio[1856]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Sep 16 18:30:10 rotel volumio[1856]: Require stack: Sep 16 18:30:10 rotel volumio[1856]: - /volumio/app/pluginmanager.js Sep 16 18:30:10 rotel volumio[1856]: - /volumio/app/index.js Sep 16 18:30:10 rotel volumio[1856]: - /volumio/index.js Sep 16 18:30:10 rotel volumio[1856]: error: Stack trace: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Sep 16 18:30:10 rotel volumio[1856]: Require stack: Sep 16 18:30:10 rotel volumio[1856]: - /volumio/app/pluginmanager.js Sep 16 18:30:10 rotel volumio[1856]: - /volumio/app/index.js Sep 16 18:30:10 rotel volumio[1856]: - /volumio/index.js Sep 16 18:30:10 rotel volumio[1856]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Sep 16 18:30:10 rotel volumio[1856]: at Module._load (node:internal/modules/cjs/loader:901:27) Sep 16 18:30:10 rotel volumio[1856]: at Module.require (node:internal/modules/cjs/loader:1115:19) Sep 16 18:30:10 rotel volumio[1856]: at require (node:internal/modules/helpers:130:18) Sep 16 18:30:10 rotel volumio[1856]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Sep 16 18:30:10 rotel volumio[1856]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Sep 16 18:30:10 rotel volumio[1856]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Sep 16 18:30:10 rotel volumio[1856]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Sep 16 18:30:10 rotel volumio[1856]: error: !!!! WARNING !!!! Sep 16 18:30:10 rotel volumio[1856]: info: Done. Sep 16 18:30:15 rotel volumio[1856]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 16 18:30:18 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 16 18:30:18 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 16 18:30:22 rotel volumio[1856]: info: Starting Uninstall of plugin user_interface - now_playing Sep 16 18:30:22 rotel volumio[1856]: info: Uninstalling plugin now_playing Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 16 18:30:22 rotel volumio[1856]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Sep 16 18:30:22 rotel volumio[1856]: error: Failed callmethod call: TypeError: Cannot read properties of null (reading 'broadcastMessage') Sep 16 18:30:22 rotel volumio[1856]: info: Received Get System Version Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 16 18:30:22 rotel volumio[1856]: info: Received Get System Info Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 16 18:30:22 rotel volumio[1856]: info: Discovery: Getting this device information Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::volumioGetState Sep 16 18:30:22 rotel volumio[1856]: info: CorePlayQueue::getTrack 0 Sep 16 18:30:22 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 16 18:30:38 rotel volumio[1856]: info: Starting Uninstall of plugin user_interface - now_playing Sep 16 18:30:38 rotel volumio[1856]: info: Uninstalling plugin now_playing Sep 16 18:30:40 rotel volumio[1856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 16 18:30:43 rotel volumio[1856]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/now_playing/1.0.2/volumio/bookworm/armhf Sep 16 18:30:43 rotel volumio[1856]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 16 18:30:43 rotel volumio[1856]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Sep 16 18:30:43 rotel volumio[1856]: at /volumio/app/index.js:1534:32 Sep 16 18:30:43 rotel volumio[1856]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Sep 16 18:30:43 rotel volumio[1856]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Sep 16 18:30:43 rotel volumio[1856]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Sep 16 18:30:43 rotel volumio[1856]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Sep 16 18:30:43 rotel volumio[1856]: at PluginManager.installPlugin (/volumio/app/pluginmanager.js:776:8) Sep 16 18:30:43 rotel volumio[1856]: at CoreCommandRouter.installPlugin (/volumio/app/index.js:1453:22) Sep 16 18:30:43 rotel volumio[1856]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1209:47) Sep 16 18:30:43 rotel volumio[1856]: at Socket.emit (node:events:514:28) Sep 16 18:30:43 rotel volumio[1856]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Sep 16 18:30:43 rotel volumio[1856]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Sep 16 18:30:43 rotel volumio[1856]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 16 18:30:43 rotel sudo[16554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-16 18:29' Sep 16 18:30:43 rotel sudo[16554]: 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="dfc7bb04e09bf2260691765a2340814af1fa2971" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="30d63a8c53d2826bd7f262e22b4e4511a4cc9d01" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Aug 30 06:39:32 UTC 2025" VOLUMIO_VERSION="4.022" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e7b0bd0cb5661ea77402e5bd121ec64a"