Feb 11 11:51:11 volumio volumio[23629]: info: Checking if install.sh is present Feb 11 11:51:11 volumio volumio[23629]: info: Executing install.sh Feb 11 11:51:11 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186:3000 from 192.168.5.227 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Feb 11 11:51:11 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186:3000 from 192.168.5.227 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Feb 11 11:51:11 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186:3000 from 192.168.5.227 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Feb 11 11:51:11 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186:3000 from 192.168.5.227 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Feb 11 11:51:11 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 11 11:51:11 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 11 11:51:11 volumio volumio[23629]: info: Discovery: Getting this device information Feb 11 11:51:11 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:11 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:11 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 11 11:51:11 volumio sudo[24246]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/now_playing/install.sh Feb 11 11:51:11 volumio sudo[24246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 11 11:51:11 volumio volumio[23629]: info: Installing geo-tz node dependency Feb 11 11:51:11 volumio su[24249]: (to volumio) root on none Feb 11 11:51:11 volumio su[24249]: pam_unix(su:session): session opened for user volumio(uid=1000) by (uid=0) Feb 11 11:51:11 volumio systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. Feb 11 11:51:11 volumio systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Feb 11 11:51:11 volumio systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Feb 11 11:51:11 volumio systemd[1]: Starting user@1000.service - User Manager for UID 1000... Feb 11 11:51:11 volumio (systemd)[24251]: pam_unix(systemd-user:session): session opened for user volumio(uid=1000) by (uid=0) Feb 11 11:51:12 volumio sudo[24267]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 11 11:51:12 volumio sudo[24267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 11 11:51:12 volumio sudo[24267]: pam_unix(sudo:session): session closed for user root Feb 11 11:51:12 volumio sudo[24269]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 11 11:51:12 volumio sudo[24269]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 11 11:51:12 volumio sudo[24269]: pam_unix(sudo:session): session closed for user root Feb 11 11:51:12 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186 from 192.168.5.227 UA: Mozilla/5.0 (Linux; Android 16; SM-S908B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Feb 11 11:51:12 volumio sudo[24273]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 11 11:51:12 volumio sudo[24273]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 11 11:51:12 volumio sudo[24273]: pam_unix(sudo:session): session closed for user root Feb 11 11:51:12 volumio sudo[24275]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 11 11:51:12 volumio sudo[24275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 11 11:51:12 volumio sudo[24275]: pam_unix(sudo:session): session closed for user root Feb 11 11:51:12 volumio volumio[23629]: verbose: New Socket.io Connection to 192.168.5.186 from 192.168.5.227 UA: Mozilla/5.0 (Linux; Android 16; SM-S908B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/144.0.7559.132 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Feb 11 11:51:12 volumio systemd[24251]: Queued start job for default target default.target. Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::volumioGetVisibleSources Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:12 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 11 11:51:12 volumio volumio[23629]: info: Received Get System Info Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 11 11:51:12 volumio volumio[23629]: info: Discovery: Getting this device information Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:12 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:12 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:12 volumio volumio[23629]: info: Listing playlists Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 11 11:51:12 volumio systemd[24251]: Created slice app.slice - User Application Slice. Feb 11 11:51:12 volumio systemd[24251]: Reached target paths.target - Paths. Feb 11 11:51:12 volumio systemd[24251]: Reached target timers.target - Timers. Feb 11 11:51:12 volumio systemd[24251]: Starting dbus.socket - D-Bus User Message Bus Socket... Feb 11 11:51:12 volumio systemd[24251]: Listening on dirmngr.socket - GnuPG network certificate management daemon. Feb 11 11:51:12 volumio systemd[24251]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Feb 11 11:51:12 volumio systemd[24251]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Feb 11 11:51:12 volumio systemd[24251]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Feb 11 11:51:12 volumio systemd[24251]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Feb 11 11:51:12 volumio systemd[24251]: Listening on dbus.socket - D-Bus User Message Bus Socket. Feb 11 11:51:12 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 11 11:51:12 volumio systemd[24251]: Reached target sockets.target - Sockets. Feb 11 11:51:12 volumio systemd[24251]: Reached target basic.target - Basic System. Feb 11 11:51:12 volumio systemd[1]: Started user@1000.service - User Manager for UID 1000. Feb 11 11:51:12 volumio systemd[24251]: Started mpris-proxy.service - Bluetooth mpris proxy. Feb 11 11:51:12 volumio systemd[24251]: Reached target default.target - Main User Target. Feb 11 11:51:12 volumio systemd[24251]: Startup finished in 791ms. Feb 11 11:51:12 volumio systemd[1]: Started session-c1.scope - Session c1 of User volumio. Feb 11 11:51:12 volumio systemd[24251]: Created slice session.slice - User Core Session Slice. Feb 11 11:51:12 volumio systemd[24251]: Starting dbus.service - D-Bus User Message Bus... Feb 11 11:51:12 volumio systemd[24251]: Started dbus.service - D-Bus User Message Bus. Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 11 11:51:14 volumio volumio[23629]: info: Received Get System Info Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 11 11:51:14 volumio volumio[23629]: info: Discovery: Getting this device information Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:14 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:14 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 11 11:51:15 volumio volumio[23629]: info: Received Get System Info Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 11 11:51:15 volumio volumio[23629]: info: Discovery: Getting this device information Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:15 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 11 11:51:15 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 11 11:51:16 volumio volumio[23629]: info: Enabling plugin now_playing Feb 11 11:51:16 volumio volumio[23629]: info: Loading plugin "now_playing"... Feb 11 11:51:17 volumio volumio[23629]: error: !!!! WARNING !!!! Feb 11 11:51:17 volumio volumio[23629]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Feb 11 11:51:17 volumio volumio[23629]: Require stack: Feb 11 11:51:17 volumio volumio[23629]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/app/pluginmanager.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/app/index.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/index.js Feb 11 11:51:17 volumio volumio[23629]: error: Stack trace: Error: Cannot find module 'geo-tz' Feb 11 11:51:17 volumio volumio[23629]: Require stack: Feb 11 11:51:17 volumio volumio[23629]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/app/pluginmanager.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/app/index.js Feb 11 11:51:17 volumio volumio[23629]: - /volumio/index.js Feb 11 11:51:17 volumio volumio[23629]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Feb 11 11:51:17 volumio volumio[23629]: at Module._load (node:internal/modules/cjs/loader:901:27) Feb 11 11:51:17 volumio volumio[23629]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 11 11:51:17 volumio volumio[23629]: at require (node:internal/modules/helpers:130:18) Feb 11 11:51:17 volumio volumio[23629]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Feb 11 11:51:17 volumio volumio[23629]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Feb 11 11:51:17 volumio volumio[23629]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Feb 11 11:51:17 volumio volumio[23629]: at Module.load (node:internal/modules/cjs/loader:1091:32) Feb 11 11:51:17 volumio volumio[23629]: at Module._load (node:internal/modules/cjs/loader:938:12) Feb 11 11:51:17 volumio volumio[23629]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 11 11:51:17 volumio volumio[23629]: at require (node:internal/modules/helpers:130:18) Feb 11 11:51:17 volumio volumio[23629]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Feb 11 11:51:17 volumio volumio[23629]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Feb 11 11:51:17 volumio volumio[23629]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Feb 11 11:51:17 volumio volumio[23629]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Feb 11 11:51:17 volumio volumio[23629]: error: !!!! WARNING !!!! Feb 11 11:51:17 volumio volumio[23629]: info: Done. Feb 11 11:51:17 volumio volumio[23629]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 11 11:51:22 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 11 11:51:25 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 11 11:51:25 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 11 11:51:30 volumio volumio[23629]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 11 11:51:30 volumio volumio[23629]: error: Failed callmethod call: TypeError: Cannot read properties of null (reading 'broadcastMessage') Feb 11 11:51:30 volumio volumio[23629]: info: Received Get System Version Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 11 11:51:30 volumio volumio[23629]: info: Received Get System Info Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 11 11:51:30 volumio volumio[23629]: info: Discovery: Getting this device information Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::volumioGetState Feb 11 11:51:30 volumio volumio[23629]: info: CorePlayQueue::getTrack 0 Feb 11 11:51:30 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 11 11:51:37 volumio volumio[23629]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 11 11:52:21 volumio volumio[23629]: info: Feb 11 11:52:21 volumio volumio[23629]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 11 11:52:21 volumio volumio[23629]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Feb 11 11:52:21 volumio volumio[23629]: at /volumio/app/index.js:1534:32 Feb 11 11:52:21 volumio volumio[23629]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Feb 11 11:52:21 volumio volumio[23629]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Feb 11 11:52:21 volumio volumio[23629]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Feb 11 11:52:21 volumio volumio[23629]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Feb 11 11:52:21 volumio volumio[23629]: at Tail. (/volumio/app/pluginmanager.js:860:24) Feb 11 11:52:21 volumio volumio[23629]: at Tail.emit (node:events:514:28) Feb 11 11:52:21 volumio volumio[23629]: at ReadStream. (/volumio/node_modules/tail/lib/tail.js:51:33) Feb 11 11:52:21 volumio volumio[23629]: at ReadStream.emit (node:events:514:28) Feb 11 11:52:21 volumio volumio[23629]: at addChunk (node:internal/streams/readable:343:12) Feb 11 11:52:21 volumio volumio[23629]: at readableAddChunk (node:internal/streams/readable:312:11) Feb 11 11:52:21 volumio volumio[23629]: at Readable.push (node:internal/streams/readable:253:10) Feb 11 11:52:21 volumio volumio[23629]: at node:internal/fs/streams:275:14 Feb 11 11:52:21 volumio volumio[23629]: at FSReqCallback.wrapper [as oncomplete] (node:fs:701:5) Feb 11 11:52:21 volumio volumio[23629]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 11 11:52:21 volumio su[24249]: pam_unix(su:session): session closed for user volumio Feb 11 11:52:21 volumio systemd[1]: session-c1.scope: Deactivated successfully. Feb 11 11:52:21 volumio systemd[1]: session-c1.scope: Consumed 55.835s CPU time. Feb 11 11:52:21 volumio sudo[24246]: pam_unix(sudo:session): session closed for user root Feb 11 11:52:22 volumio sudo[24443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-11 11:51' Feb 11 11:52:22 volumio sudo[24443]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"