-- Logs begin at Thu 2019-02-14 05:11:58 EST, end at Sun 2025-05-25 21:33:13 EDT. -- May 25 21:32:00 volumiorpi4 wireless.js[607]: trying... May 25 21:32:00 volumiorpi4 sudo[947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:00 volumiorpi4 sudo[947]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:00 volumiorpi4 sudo[947]: pam_unix(sudo:session): session closed for user root May 25 21:32:00 volumiorpi4 dhcpcd[909]: wlan0: rebinding lease of 192.168.4.43 May 25 21:32:00 volumiorpi4 dhcpcd[909]: wlan0: probing address 192.168.4.43/22 May 25 21:32:00 volumiorpi4 dhcpcd[909]: wlan0: soliciting an IPv6 router May 25 21:32:00 volumiorpi4 volumio-remote-updater[597]: [2025-05-25 21:32:00] [info] asio async_connect error: system:111 (Connection refused) May 25 21:32:00 volumiorpi4 volumio-remote-updater[597]: [2025-05-25 21:32:00] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) May 25 21:32:00 volumiorpi4 volumio-remote-updater[597]: [2025-05-25 21:32:00] [error] handle_connect error: Underlying Transport Error May 25 21:32:01 volumiorpi4 wireless.js[607]: trying... May 25 21:32:01 volumiorpi4 sudo[950]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:01 volumiorpi4 sudo[950]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:01 volumiorpi4 sudo[950]: pam_unix(sudo:session): session closed for user root May 25 21:32:02 volumiorpi4 wireless.js[607]: trying... May 25 21:32:02 volumiorpi4 sudo[953]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:02 volumiorpi4 sudo[953]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:02 volumiorpi4 sudo[953]: pam_unix(sudo:session): session closed for user root May 25 21:32:02 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: Fetching time from Volumio... May 25 21:32:02 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: Date not found in response May 25 21:32:02 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: Retrying in 5 seconds... May 25 21:32:03 volumiorpi4 wireless.js[607]: trying... May 25 21:32:03 volumiorpi4 sudo[961]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:03 volumiorpi4 sudo[961]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:03 volumiorpi4 sudo[961]: pam_unix(sudo:session): session closed for user root May 25 21:32:04 volumiorpi4 wireless.js[607]: trying... May 25 21:32:04 volumiorpi4 sudo[964]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:04 volumiorpi4 sudo[964]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:04 volumiorpi4 sudo[964]: pam_unix(sudo:session): session closed for user root May 25 21:32:05 volumiorpi4 wireless.js[607]: trying... May 25 21:32:05 volumiorpi4 sudo[967]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:05 volumiorpi4 sudo[967]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:05 volumiorpi4 sudo[967]: pam_unix(sudo:session): session closed for user root May 25 21:32:05 volumiorpi4 dhcpcd[909]: wlan0: leased 192.168.4.43 for 14227 seconds May 25 21:32:05 volumiorpi4 avahi-daemon[592]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.4.43. May 25 21:32:05 volumiorpi4 avahi-daemon[592]: New relevant interface wlan0.IPv4 for mDNS. May 25 21:32:05 volumiorpi4 avahi-daemon[592]: Registering new address record for 192.168.4.43 on wlan0.IPv4. May 25 21:32:05 volumiorpi4 dhcpcd[909]: wlan0: adding route to 192.168.4.0/22 May 25 21:32:05 volumiorpi4 dhcpcd[909]: wlan0: adding default route via 192.168.4.1 May 25 21:32:06 volumiorpi4 wireless.js[607]: trying... May 25 21:32:06 volumiorpi4 sudo[990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r May 25 21:32:06 volumiorpi4 sudo[990]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:06 volumiorpi4 sudo[990]: pam_unix(sudo:session): session closed for user root May 25 21:32:06 volumiorpi4 wireless.js[607]: Connected to: ----Stingingbee May 25 21:32:06 volumiorpi4 wireless.js[607]: ---- May 25 21:32:06 volumiorpi4 sudo[993]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 25 21:32:06 volumiorpi4 sudo[993]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:06 volumiorpi4 sudo[993]: pam_unix(sudo:session): session closed for user root May 25 21:32:06 volumiorpi4 wireless.js[607]: ... joined AP, wlan0 IPv4 is 192.168.4.43, ipV6 is undefined May 25 21:32:06 volumiorpi4 wireless.js[607]: It's done! AP May 25 21:32:06 volumiorpi4 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 25 21:32:06 volumiorpi4 systemd[1]: Started Wireless Services. May 25 21:32:06 volumiorpi4 systemd[1]: Started Volumio Backend Module. May 25 21:32:06 volumiorpi4 systemd[1]: Started Volumio Cpu Tweaker. May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: Setting RT Priority for mpd May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: Setting MPD Affinity May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: pid 810's current affinity mask: f May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: pid 810's new affinity mask: 3 May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input May 25 21:32:06 volumiorpi4 volumio-cpu-tweak[999]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance May 25 21:32:06 volumiorpi4 systemd[1]: volumio_cpu_tweak.service: Succeeded. May 25 21:32:07 volumiorpi4 ntpd[767]: Listen normally on 3 wlan0 192.168.4.43:123 May 25 21:32:07 volumiorpi4 ntpd[767]: new interface(s) found: waking up resolver May 25 21:32:07 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:07 volumiorpi4 volumio[998]: info: ----- Volumio3 ---- May 25 21:32:07 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:07 volumiorpi4 volumio[998]: info: ----- System startup ---- May 25 21:32:07 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:07 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: Fetching time from Volumio... May 25 21:32:08 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: Setting system time to: 2025-05-25 21:32:35 May 25 21:32:08 volumiorpi4 sudo[1028]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-05-25 21:32:35 May 25 21:32:08 volumiorpi4 sudo[1028]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:08 volumiorpi4 dbus-daemon[598]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.9' (uid=0 pid=1029 comm="timedatectl set-time 2025-05-25 21:32:35 ") May 25 21:32:08 volumiorpi4 systemd[1]: Starting Time & Date Service... May 25 21:32:08 volumiorpi4 dbus-daemon[598]: [system] Successfully activated service 'org.freedesktop.timedate1' May 25 21:32:08 volumiorpi4 systemd[1]: Started Time & Date Service. May 25 21:32:35 volumiorpi4 systemd-timedated[1030]: Changed local time to Sun May 25 21:32:35 2025 May 25 21:32:35 volumiorpi4 sudo[1028]: pam_unix(sudo:session): session closed for user root May 25 21:32:35 volumiorpi4 volumio-time-update[589]: volumio-time-update-util: System time updated successfully. May 25 21:32:35 volumiorpi4 systemd[1]: Started Volumio Time Update Utility. May 25 21:32:35 volumiorpi4 volumio[998]: info: MYVOLUMIO Environment detected May 25 21:32:35 volumiorpi4 volumio[998]: info: Plugin folders cleanup May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning into folder /volumio/app/plugins/ May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category audio_interface May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category miscellanea May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category music_service May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category plugins.json May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category system_controller May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category user_interface May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning into folder /data/plugins/ May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category music_service May 25 21:32:35 volumiorpi4 volumio[998]: info: Scanning category user_interface May 25 21:32:35 volumiorpi4 volumio[998]: info: Plugin folders cleanup completed May 25 21:32:35 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:35 volumiorpi4 volumio[998]: info: ----- Core plugins startup ---- May 25 21:32:35 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:35 volumiorpi4 volumio[998]: info: Loading plugins from folder /volumio/app/plugins/ May 25 21:32:35 volumiorpi4 volumio[998]: info: Adding plugin upnp to MyMusic Plugins May 25 21:32:35 volumiorpi4 volumio[998]: info: Adding plugin airplay_emulation to MyMusic Plugins May 25 21:32:35 volumiorpi4 volumio[998]: info: Adding plugin upnp_browser to MyMusic Plugins May 25 21:32:35 volumiorpi4 volumio[998]: info: Loading plugins from folder /data/plugins/ May 25 21:32:35 volumiorpi4 volumio[998]: info: Loading plugin "system"... May 25 21:32:35 volumiorpi4 volumio[998]: info: Loading plugin "appearance"... May 25 21:32:35 volumiorpi4 nmbd[744]: [2025/05/25 21:32:35.477361, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 25 21:32:35 volumiorpi4 systemd[1]: Started Samba NMB Daemon. May 25 21:32:35 volumiorpi4 nmbd[744]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 25 21:32:35 volumiorpi4 nmbd[744]: [2025/05/25 21:32:35.491619, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) May 25 21:32:35 volumiorpi4 nmbd[744]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.4.43 for name WORKGROUP<1d>. May 25 21:32:35 volumiorpi4 nmbd[744]: This response was from IP 192.168.4.45, reporting an IP address of 192.168.4.45. May 25 21:32:35 volumiorpi4 systemd[1]: Starting Samba Winbind Daemon... May 25 21:32:35 volumiorpi4 winbindd[1036]: [2025/05/25 21:32:35.736345, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 25 21:32:35 volumiorpi4 winbindd[1036]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 25 21:32:35 volumiorpi4 winbindd[1036]: [2025/05/25 21:32:35.774787, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 25 21:32:35 volumiorpi4 winbindd[1036]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 25 21:32:35 volumiorpi4 systemd[1]: Started Samba Winbind Daemon. May 25 21:32:35 volumiorpi4 systemd[1]: Starting Samba SMB Daemon... May 25 21:32:36 volumiorpi4 winbindd[1036]: [2025/05/25 21:32:36.180545, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) May 25 21:32:36 volumiorpi4 winbindd[1036]: res_names->count = 3, expected 4 May 25 21:32:36 volumiorpi4 smbd[1041]: [2025/05/25 21:32:36.198882, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 25 21:32:36 volumiorpi4 systemd[1]: Started Samba SMB Daemon. May 25 21:32:36 volumiorpi4 smbd[1041]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 25 21:32:36 volumiorpi4 systemd[1]: Reached target Multi-User System. May 25 21:32:36 volumiorpi4 systemd[1]: Reached target Graphical Interface. May 25 21:32:36 volumiorpi4 systemd[1]: Starting Update UTMP about System Runlevel Changes... May 25 21:32:36 volumiorpi4 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 25 21:32:36 volumiorpi4 systemd[1]: Started Update UTMP about System Runlevel Changes. May 25 21:32:36 volumiorpi4 systemd[1]: Startup finished in 12.124s (kernel) + 25.588s (userspace) = 37.712s. May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "network"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Refreshing Cached IP Addresses May 25 21:32:36 volumiorpi4 sudo[1051]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 25 21:32:36 volumiorpi4 sudo[1051]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:36 volumiorpi4 sudo[1051]: pam_unix(sudo:session): session closed for user root May 25 21:32:36 volumiorpi4 sudo[1053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 25 21:32:36 volumiorpi4 sudo[1053]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:36 volumiorpi4 sudo[1053]: pam_unix(sudo:session): session closed for user root May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "services"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "alsa_controller"... May 25 21:32:36 volumiorpi4 sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 25 21:32:36 volumiorpi4 sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:36 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "wizard"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "networkfs"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Starting Udev Watcher for removable devices May 25 21:32:36 volumiorpi4 sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.4.45/music /mnt/NAS/NAS May 25 21:32:36 volumiorpi4 sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:36 volumiorpi4 volumio[998]: info: Ignoring mount for partition: boot May 25 21:32:36 volumiorpi4 volumio[998]: info: Ignoring mount for partition: volumio May 25 21:32:36 volumiorpi4 volumio[998]: info: Ignoring mount for partition: volumio_data May 25 21:32:36 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "volumio_command_line_client"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "upnp"... May 25 21:32:36 volumiorpi4 volumio[998]: info: [1748223156645] Starting Upmpd Daemon May 25 21:32:36 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "my_music"... May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "mpd"... May 25 21:32:36 volumiorpi4 kernel: Key type cifs.spnego registered May 25 21:32:36 volumiorpi4 kernel: Key type cifs.idmap registered May 25 21:32:36 volumiorpi4 kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. May 25 21:32:36 volumiorpi4 kernel: CIFS: Attempting to mount //192.168.4.45/music May 25 21:32:36 volumiorpi4 volumio[998]: info: Loading plugin "upnp_browser"... May 25 21:32:37 volumiorpi4 volumio-remote-updater[597]: [2025-05-25 21:32:37] [connect] Successful connection May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "alarm-clock"... May 25 21:32:37 volumiorpi4 sudo[1077]: pam_unix(sudo:session): session closed for user root May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "airplay_emulation"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Starting Shairport Sync May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "last_100"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "webradio"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "i2s_dacs"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "volumiodiscovery"... May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** Please fix your application to use the native API of Avahi! May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** For more information see May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** Please fix your application to use the native API of Avahi! May 25 21:32:37 volumiorpi4 volumio[998]: *** WARNING *** For more information see May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** Please fix your application to use the native API of Avahi! May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** For more information see May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** Please fix your application to use the native API of Avahi! May 25 21:32:37 volumiorpi4 node[998]: *** WARNING *** For more information see May 25 21:32:37 volumiorpi4 volumio[998]: info: Applying required configuration parameters for plugin volumiodiscovery May 25 21:32:37 volumiorpi4 volumio[998]: info: Discovery: Started advertising with name: VolumioRPi4 May 25 21:32:37 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "outputs"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "albumart"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Plugin example_plugin is not enabled May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "inputs"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "updater_comm"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Plugin mpdemulation is not enabled May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "rest_api"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "websocket"... May 25 21:32:37 volumiorpi4 volumio[998]: info: Starting Socket.io Server version 2.3.0 May 25 21:32:37 volumiorpi4 volumio[998]: info: Loading plugin "motherearthradio"... May 25 21:32:37 volumiorpi4 volumio[998]: Forking 3 albumart workers May 25 21:32:38 volumiorpi4 volumio[998]: info: Applying required configuration parameters for plugin motherearthradio May 25 21:32:38 volumiorpi4 volumio[998]: info: [1748223158253] [MotherEarth] API delay: 5 May 25 21:32:38 volumiorpi4 volumio[998]: info: Loading plugin "personal_radio"... May 25 21:32:38 volumiorpi4 volumio[998]: Starting albumart workers May 25 21:32:38 volumiorpi4 volumio[998]: Starting albumart workers May 25 21:32:38 volumiorpi4 volumio[998]: Starting albumart workers May 25 21:32:38 volumiorpi4 volumio[998]: info: ControllerPersonalRadio::constructor May 25 21:32:38 volumiorpi4 volumio[998]: info: Loading plugin "radio_paradise"... May 25 21:32:39 volumiorpi4 volumio[998]: info: Applying required configuration parameters for plugin radio_paradise May 25 21:32:39 volumiorpi4 volumio[998]: info: [1748223159110] [RadioParadise] API delay: 5 May 25 21:32:39 volumiorpi4 volumio[998]: info: Loading plugin "touch_display"... May 25 21:32:39 volumiorpi4 volumio[998]: info: Applying required configuration parameters for plugin touch_display May 25 21:32:39 volumiorpi4 volumio[998]: info: Loading i18n strings for locale en May 25 21:32:39 volumiorpi4 volumio[998]: Updating browse sources language May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::initPlayerControls May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: Express server listening on port 3000 May 25 21:32:39 volumiorpi4 volumio[998]: [Metrics] WebUI: 5s 752.88ms May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::resetVolumioState May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::getcurrentVolume May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioRetrievevolume May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:39 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:39 volumiorpi4 volumio[998]: info: Volumio Network Manager: Network status updated: 2 May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43 from 192.168.4.22 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250505.005.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/136.0.7103.125 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 May 25 21:32:39 volumiorpi4 volumio-remote-updater[597]: [2025-05-25 21:32:39] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748223157 101 May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 2 May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43 from 192.168.4.22 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250505.005.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/136.0.7103.125 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43 from 192.168.4.22 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250505.005.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/136.0.7103.125 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43:3000 from 192.168.4.22 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:39 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:39 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:39 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 25 21:32:39 volumiorpi4 volumio[998]: info: Reloading queue from file May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::setRepeat true single undefined May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:39 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::setRandom false May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:39 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:39 volumiorpi4 volumio[998]: info: Setting Device type: Raspberry PI May 25 21:32:39 volumiorpi4 volumio[998]: info: Completed loading Core Plugins May 25 21:32:39 volumiorpi4 volumio[998]: info: Preparing to generate the ALSA configuration file May 25 21:32:39 volumiorpi4 volumio[998]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb May 25 21:32:39 volumiorpi4 volumio[998]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 May 25 21:32:39 volumiorpi4 volumio[998]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI May 25 21:32:39 volumiorpi4 volumio[998]: info: Asound.conf file unchanged, so no further update is needed May 25 21:32:39 volumiorpi4 volumio[998]: info: Output device has changed, restarting MPD May 25 21:32:39 volumiorpi4 sudo[1169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 25 21:32:39 volumiorpi4 sudo[1169]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:39 volumiorpi4 volumio[998]: info: Output device has changed, restarting Shairport Sync May 25 21:32:39 volumiorpi4 sudo[1062]: pam_unix(sudo:session): session closed for user root May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:39 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:39 volumiorpi4 sudo[1169]: pam_unix(sudo:session): session closed for user root May 25 21:32:40 volumiorpi4 sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 25 21:32:40 volumiorpi4 sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 systemd[1]: Stopping Music Player Daemon... May 25 21:32:40 volumiorpi4 volumio[998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 21:32:40 volumiorpi4 volumio[998]: info: ___________ START PLUGINS ___________ May 25 21:32:40 volumiorpi4 volumio[998]: info: ControllerMpd::onStart: Initializing MPD May 25 21:32:40 volumiorpi4 volumio[998]: info: Creating MPD Configuration file May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160073] CoreMusicLibrary::Adding element Media Servers May 25 21:32:40 volumiorpi4 sudo[1178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 sudo[1178]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 sudo[1178]: pam_unix(sudo:session): session closed for user root May 25 21:32:40 volumiorpi4 sudo[1180]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 25 21:32:40 volumiorpi4 sudo[1180]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:40 volumiorpi4 systemd[1]: mpd.service: Succeeded. May 25 21:32:40 volumiorpi4 systemd[1]: Stopped Music Player Daemon. May 25 21:32:40 volumiorpi4 volumio[998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:40 volumiorpi4 systemd[1]: Starting Music Player Daemon... May 25 21:32:40 volumiorpi4 volumio[998]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160168] CoreMusicLibrary::Adding element Last_100 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160170] CoreMusicLibrary::Adding element Webradio May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:32:40 volumiorpi4 volumio[998]: info: Initializing BBC Radios May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:40 volumiorpi4 sudo[1186]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 25 21:32:40 volumiorpi4 sudo[1186]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160234] CoreMusicLibrary::Adding element Mother Earth Radio May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Mother Earth Radio May 25 21:32:40 volumiorpi4 sudo[1186]: pam_unix(sudo:session): session closed for user root May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160282] CoreMusicLibrary::Adding element Personal Radio May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Mother Earth Radio May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Personal Radio May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 21:32:40 volumiorpi4 volumio[998]: info: [1748223160287] CoreMusicLibrary::Adding element Radio Paradise May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Mother Earth Radio May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Personal Radio May 25 21:32:40 volumiorpi4 volumio[998]: Cannot find translation for source Radio Paradise May 25 21:32:40 volumiorpi4 volumio[998]: info: Loading i18n strings for locale en May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:32:40 volumiorpi4 volumio[998]: info: Volumio Calling Home May 25 21:32:40 volumiorpi4 sudo[1206]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service May 25 21:32:40 volumiorpi4 sudo[1206]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 sudo[1208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service May 25 21:32:40 volumiorpi4 sudo[1208]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 sudo[1211]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload May 25 21:32:40 volumiorpi4 sudo[1211]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 volumio[998]: info: Discovery: adding f7e7d7f4-4a85-4324-a102-5197bc5aa8b8 May 25 21:32:40 volumiorpi4 volumio[998]: info: Discovery: Found device VolumioRPi4 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:40 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:40 volumiorpi4 systemd[1]: Reloading. May 25 21:32:40 volumiorpi4 volumio[998]: error: touch_display: Error detecting backlight interface: Error: ENOENT: no such file or directory, scandir '/sys/class/backlight/' May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetVisibleSources May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:40 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 25 21:32:40 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:40 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:40 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:40 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:40 volumiorpi4 volumio[998]: info: Listing playlists May 25 21:32:40 volumiorpi4 volumio[998]: info: MPD Permissions set May 25 21:32:40 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43:3000 from 192.168.4.22 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:40 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard May 25 21:32:40 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:40 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:32:40 volumiorpi4 systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. May 25 21:32:40 volumiorpi4 volumio[998]: info: Volumio called home May 25 21:32:40 volumiorpi4 volumio[998]: info: touch_display: No Raspberry Pi Foundation touch screen detected. May 25 21:32:40 volumiorpi4 sudo[1236]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf May 25 21:32:40 volumiorpi4 sudo[1236]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 sudo[1236]: pam_unix(sudo:session): session closed for user root May 25 21:32:40 volumiorpi4 volumio[998]: info: Starting Shairport Sync May 25 21:32:40 volumiorpi4 volumio[998]: info: Starting Shairport Sync May 25 21:32:40 volumiorpi4 sudo[1239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 21:32:40 volumiorpi4 sudo[1239]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:40 volumiorpi4 volumio[998]: info: Starting Shairport Sync May 25 21:32:40 volumiorpi4 sudo[1241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 21:32:41 volumiorpi4 sudo[1241]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:41 volumiorpi4 systemd[1]: ifup@eth0.service: Current command vanished from the unit file, execution of the command list won't be resumed. May 25 21:32:41 volumiorpi4 sudo[1245]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 21:32:41 volumiorpi4 sudo[1245]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:41 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:41 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. May 25 21:32:41 volumiorpi4 volumio[998]: (node:998) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. May 25 21:32:41 volumiorpi4 volumio[998]: (Use `node --trace-deprecation ...` to show where the warning was created) May 25 21:32:41 volumiorpi4 volumio[998]: (node:998) [DEP0106] DeprecationWarning: crypto.createDecipher is deprecated. May 25 21:32:41 volumiorpi4 mpd[1201]: May 25 21:32 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 25 21:32:41 volumiorpi4 sudo[1211]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 systemd[1]: Started Music Player Daemon. May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: systemctl daemon-reload succeeded. May 25 21:32:41 volumiorpi4 sudo[1171]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 sudo[1206]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 sudo[1180]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 systemd[1]: Reloading. May 25 21:32:41 volumiorpi4 sudo[1250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service May 25 21:32:41 volumiorpi4 sudo[1250]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: systemctl stop getty@tty1.service succeeded. May 25 21:32:41 volumiorpi4 volumio[998]: error: MPD error: The expression evaluated to a falsy value: May 25 21:32:41 volumiorpi4 volumio[998]: assert.ok(self.idling) May 25 21:32:41 volumiorpi4 volumio[998]: error: The expression evaluated to a falsy value: May 25 21:32:41 volumiorpi4 volumio[998]: assert.ok(self.idling) May 25 21:32:41 volumiorpi4 volumio[998]: error: updateQueue error: null May 25 21:32:41 volumiorpi4 volumio[998]: info: MPD running with PID1201 May 25 21:32:41 volumiorpi4 volumio[998]: ,establishing connection May 25 21:32:41 volumiorpi4 volumio[998]: error: updateQueue error: null May 25 21:32:41 volumiorpi4 systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. May 25 21:32:41 volumiorpi4 sudo[1208]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: systemctl disable getty@tty1.service succeeded. May 25 21:32:41 volumiorpi4 systemd[1]: Started Volumio Kiosk. May 25 21:32:41 volumiorpi4 sudo[1250]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 25 21:32:41 volumiorpi4 systemd[1]: shairport-sync.service: Succeeded. May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: systemctl start volumio-kiosk.service succeeded. May 25 21:32:41 volumiorpi4 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: Volumio Kiosk started. May 25 21:32:41 volumiorpi4 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 25 21:32:41 volumiorpi4 sudo[1239]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 sudo[1245]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 sudo[1241]: pam_unix(sudo:session): session closed for user root May 25 21:32:41 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:41 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:41 volumiorpi4 volumio[998]: info: Completed starting Core Plugins May 25 21:32:41 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:41 volumiorpi4 volumio[998]: info: ----- MyVolumio plugins startup ---- May 25 21:32:41 volumiorpi4 volumio[998]: info: ------------------------------------------- May 25 21:32:41 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Fetching plans data.... May 25 21:32:41 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:41 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:41 volumiorpi4 volumio[998]: info: Shairport-Sync Started May 25 21:32:41 volumiorpi4 volumio[998]: Error adding Membership: Error: addMembership EINVAL May 25 21:32:41 volumiorpi4 volumio[998]: info: Shairport-Sync Started May 25 21:32:41 volumiorpi4 volumio[998]: info: Shairport-Sync Started May 25 21:32:41 volumiorpi4 volumio[998]: info: touch_display: X display number found: May 25 21:32:41 volumiorpi4 startx[1268]: X.Org X Server 1.20.4 May 25 21:32:41 volumiorpi4 startx[1268]: X Protocol Version 11, Revision 0 May 25 21:32:41 volumiorpi4 startx[1268]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian May 25 21:32:41 volumiorpi4 startx[1268]: Current Operating System: Linux volumiorpi4 6.6.62-v7l+ #1816 SMP Mon Nov 18 15:33:33 GMT 2024 armv7l May 25 21:32:41 volumiorpi4 startx[1268]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=1824 bcm2708_fb.fbheight=984 bcm2708_fb.fbswap=1 smsc95xx.macaddr=D8:3A:DD:71:F0:DD vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=0c3a77ec-ae84-4f1b-8028-c61cc251ffe5 imgfile=/volumio_current.sqsh bootpart=UUID=41CA-9A8B datapart=UUID=0324d53a-d066-482b-b659-eb98af2b49e7 uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no May 25 21:32:41 volumiorpi4 startx[1268]: Build Date: 04 April 2023 07:50:56AM May 25 21:32:41 volumiorpi4 startx[1268]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) May 25 21:32:41 volumiorpi4 startx[1268]: Current version of pixman: 0.36.0 May 25 21:32:41 volumiorpi4 startx[1268]: Before reporting problems, check http://wiki.x.org May 25 21:32:41 volumiorpi4 startx[1268]: to make sure that you have the latest version. May 25 21:32:41 volumiorpi4 startx[1268]: Markers: (--) probed, (**) from config file, (==) default setting, May 25 21:32:41 volumiorpi4 startx[1268]: (++) from command line, (!!) notice, (II) informational, May 25 21:32:41 volumiorpi4 startx[1268]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. May 25 21:32:41 volumiorpi4 startx[1268]: (==) Log file: "/var/log/Xorg.0.log", Time: Sun May 25 21:32:41 2025 May 25 21:32:41 volumiorpi4 startx[1268]: (==) Using config directory: "/etc/X11/xorg.conf.d" May 25 21:32:41 volumiorpi4 startx[1268]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" May 25 21:32:42 volumiorpi4 volumio[998]: info: touch_display: X display number found: 0 May 25 21:32:42 volumiorpi4 volumio[998]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 May 25 21:32:42 volumiorpi4 volumio[998]: info: touch_display: X display number found: 0 May 25 21:32:42 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43 from 192.168.4.22 UA: Mozilla/5.0 (Linux; Android 15; Pixel 7 Pro Build/BP1A.250505.005.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/136.0.7103.125 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetVisibleSources May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:42 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 25 21:32:42 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:42 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:42 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:42 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:42 volumiorpi4 volumio[998]: info: Listing playlists May 25 21:32:42 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:42 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:42 volumiorpi4 volumio[998]: info: touch_display: Setting screensaver timeout to 1200 seconds. May 25 21:32:43 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:43 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:43 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:43 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:43 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:43 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:43 volumiorpi4 systemd[1]: systemd-fsckd.service: Succeeded. May 25 21:32:44 volumiorpi4 sh[533]: timed out May 25 21:32:44 volumiorpi4 dhcpcd[587]: timed out May 25 21:32:44 volumiorpi4 sh[533]: dhcpcd exited May 25 21:32:44 volumiorpi4 dhcpcd[587]: dhcpcd exited May 25 21:32:44 volumiorpi4 sh[533]: ifup: failed to bring up eth0 May 25 21:32:44 volumiorpi4 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 25 21:32:44 volumiorpi4 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 25 21:32:45 volumiorpi4 systemd[1]: systemd-hostnamed.service: Succeeded. May 25 21:32:46 volumiorpi4 volumio[998]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 25 21:32:46 volumiorpi4 sudo[1431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 25 21:32:46 volumiorpi4 sudo[1431]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:46 volumiorpi4 sudo[1431]: pam_unix(sudo:session): session closed for user root May 25 21:32:46 volumiorpi4 sudo[1433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 25 21:32:46 volumiorpi4 sudo[1433]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:46 volumiorpi4 sudo[1433]: pam_unix(sudo:session): session closed for user root May 25 21:32:46 volumiorpi4 sudo[1439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 25 21:32:46 volumiorpi4 sudo[1439]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:46 volumiorpi4 systemd[1]: Started UPnP Renderer front-end to MPD. May 25 21:32:46 volumiorpi4 sudo[1439]: pam_unix(sudo:session): session closed for user root May 25 21:32:46 volumiorpi4 volumio[998]: info: Upmpdcli Daemon Started May 25 21:32:46 volumiorpi4 volumio[1441]: Generating RSA private key, 4096 bit long modulus (2 primes) May 25 21:32:48 volumiorpi4 volumio[1441]: ............++++ May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin bluetooth to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin multiroom to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin metavolumio to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin cd_controller to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin qobuzconnect to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin smart_inputs to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: Adding plugin tidalconnect to MyMusic Plugins May 25 21:32:50 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 25 21:32:51 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 25 21:32:51 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 25 21:32:51 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:51 volumiorpi4 volumio[998]: info: Starting MyVolumio Remote Streaming Endpoints May 25 21:32:51 volumiorpi4 volumio[998]: info: MyVolumio login type: Token May 25 21:32:51 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 25 21:32:51 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 25 21:32:52 volumiorpi4 volumio[998]: info: Starting Streaming Service Transparent Proxy May 25 21:32:52 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 25 21:32:52 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 25 21:32:52 volumiorpi4 volumio[998]: info: Streaming services startup May 25 21:32:52 volumiorpi4 volumio[998]: info: Starting Streaming Daemon May 25 21:32:52 volumiorpi4 sudo[1548]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 25 21:32:52 volumiorpi4 sudo[1548]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:52 volumiorpi4 sudo[1548]: pam_unix(sudo:session): session closed for user root May 25 21:32:52 volumiorpi4 volumio[998]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 25 21:32:52 volumiorpi4 volumio[998]: error: Cannot start Volumio Streaming Daemon May 25 21:32:52 volumiorpi4 volumio[998]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 25 21:32:52 volumiorpi4 volumio[998]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 25 21:32:52 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 May 25 21:32:52 volumiorpi4 volumio[998]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 25 21:32:53 volumiorpi4 volumio[998]: STREAMING PROXY: Starting server on port 3245 May 25 21:32:53 volumiorpi4 volumio[998]: Node JS runtime: 14 May 25 21:32:53 volumiorpi4 volumio[998]: info: MyVolumio token set successfully May 25 21:32:53 volumiorpi4 volumio[998]: info: MYVOLUMIO: Adding device May 25 21:32:53 volumiorpi4 volumio[998]: info: MYVOLUMIO: Evaluating Server May 25 21:32:53 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 May 25 21:32:53 volumiorpi4 volumio[998]: info: MyVolumio status changed May 25 21:32:53 volumiorpi4 volumio[998]: info: Streaming services startup May 25 21:32:53 volumiorpi4 volumio[998]: info: Starting Streaming Daemon May 25 21:32:53 volumiorpi4 volumio[998]: info: Removing browser output: myVolumio user plan is not superstar May 25 21:32:53 volumiorpi4 volumio[998]: info: Removing audio output: May 25 21:32:53 volumiorpi4 volumio[998]: info: Stoppping Tunnel 1 May 25 21:32:53 volumiorpi4 sudo[1573]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 25 21:32:53 volumiorpi4 sudo[1573]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:53 volumiorpi4 sudo[1573]: pam_unix(sudo:session): session closed for user root May 25 21:32:53 volumiorpi4 volumio[998]: error: Cannot start Volumio Streaming Daemon May 25 21:32:53 volumiorpi4 volumio[998]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 25 21:32:53 volumiorpi4 volumio[998]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 25 21:32:53 volumiorpi4 sudo[1576]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service May 25 21:32:53 volumiorpi4 sudo[1576]: pam_unix(sudo:session): session opened for user root by (uid=0) May 25 21:32:54 volumiorpi4 sudo[1576]: pam_unix(sudo:session): session closed for user root May 25 21:32:54 volumiorpi4 volumio[998]: info: Remote SSH Stopped May 25 21:32:54 volumiorpi4 volumio[998]: info: Setting Geolocation for MyVolumio to us3 May 25 21:32:54 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:54 volumiorpi4 volumio[1441]: ..................................................................++++ May 25 21:32:54 volumiorpi4 volumio[1441]: e is 65537 (0x010001) May 25 21:32:54 volumiorpi4 volumio[1441]: writing RSA key May 25 21:32:54 volumiorpi4 volumio[998]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 25 21:32:55 volumiorpi4 volumio[998]: info: Updating MyVolumio device info May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:55 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetVisibleSources May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 25 21:32:55 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:55 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: Listing playlists May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetVisibleSources May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 25 21:32:55 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:55 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: Listing playlists May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 25 21:32:55 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:55 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:55 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:55 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:56 volumiorpi4 volumio[998]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPlay May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::play index undefined May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::startPlaybackTimer May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand stop May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand stop took 18 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand clear May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 25 21:32:57 volumiorpi4 volumio[998]: info: Received Get System Info May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:32:57 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand clear took 5 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand consume 1 May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: error: updateQueue error: null May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: options May 25 21:32:57 volumiorpi4 volumio[998]: error: updateQueue error: null May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 6ms May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand consume 1 took 5 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 5ms May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 4ms May 25 21:32:57 volumiorpi4 volumio[998]: info: [1748223177446] [RadioParadise] set to consume mode, adding url: https://stream.radioparadise.com/flac May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand add "https://stream.radioparadise.com/flac" May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: options May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: options May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand status took 5 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand add "https://stream.radioparadise.com/flac" took 5 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand status took 4 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand status took 3 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand play May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:57 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:57 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::pushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 29ms May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 32ms May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 32ms May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: info: May 25 21:32:57 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:32:57 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 36ms May 25 21:32:57 volumiorpi4 volumio[998]: info: sendMpdCommand play took 30 milliseconds May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 5ms May 25 21:32:57 volumiorpi4 volumio[998]: info: ------------------------------ 4ms May 25 21:32:57 volumiorpi4 volumio[998]: info: [1748223177487] [RadioParadise] getMetadata started with url https://api.radioparadise.com/api/now_playing?chan=0 May 25 21:32:57 volumiorpi4 volumio[998]: info: [1748223177942] [RadioParadise] received new metadata: {"time":214,"artist":"Doves","title":"The Greatest Denier","album":"Kingdom of Rust","year":"2009","cover":"https://img.radioparadise.com/covers/l/B001QFNSCK.jpg","cover_med":"https://img.radioparadise.com/covers/m/B001QFNSCK.jpg","cover_small":"https://img.radioparadise.com/covers/s/B001QFNSCK.jpg"} May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:57 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:57 volumiorpi4 volumio[998]: verbose: STATE SERVICE {"status":"play","service":"radio_paradise","type":"webradio","trackType":"flac","radioType":"rparadise","albumart":"https://img.radioparadise.com/covers/l/B001QFNSCK.jpg","uri":"https://stream.radioparadise.com/flac","name":"The Greatest Denier","title":"The Greatest Denier","artist":"Doves","album":"Kingdom of Rust","streaming":true,"disableUiControls":true,"duration":219,"seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} May 25 21:32:57 volumiorpi4 volumio[998]: verbose: CURRENT POSITION 0 May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::syncState stateService play May 25 21:32:57 volumiorpi4 volumio[998]: info: CoreStateMachine::syncState currentStatus stop May 25 21:32:57 volumiorpi4 volumio[998]: info: [1748223177945] [RadioParadise] setting new timer with duration of 219000 seconds. May 25 21:32:58 volumiorpi4 volumio[998]: info: MYVOLUMIO: Adding device May 25 21:32:58 volumiorpi4 volumio[998]: info: MYVOLUMIO: Evaluating Server May 25 21:32:59 volumiorpi4 volumio[998]: info: Setting Geolocation for MyVolumio to us3 May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:32:59 volumiorpi4 volumio[998]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 8 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 9 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 9 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 2 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 15ms May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: May 25 21:32:59 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 8 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 7 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 7 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 3 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand status took 2 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 23ms May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 22ms May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 5 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 4 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 3 milliseconds May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:32:59 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:32:59 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 18ms May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 13ms May 25 21:32:59 volumiorpi4 volumio[998]: info: ------------------------------ 12ms May 25 21:33:00 volumiorpi4 volumio[998]: info: Updating MyVolumio device info May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:33:00 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:33:00 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces system playlist update May 25 21:33:00 volumiorpi4 volumio[998]: info: Ignoring MPD Status Update May 25 21:33:00 volumiorpi4 volumio[998]: info: May 25 21:33:00 volumiorpi4 volumio[998]: ---------------------------- MPD announces state update: player May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::getState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand status May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 6ms May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand status took 4 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 3ms May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand status took 3 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 3ms May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand status took 2 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseState May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 2 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 1 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: info: sendMpdCommand playlistinfo took 1 milliseconds May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:33:00 volumiorpi4 volumio[998]: verbose: ControllerMpd::parseTrackInfo May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:00 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:00 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:33:00 volumiorpi4 volumio[998]: info: ControllerMpd::pushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CoreCommandRouter::servicePushState May 25 21:33:00 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:00 volumiorpi4 volumio[998]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current radio_paradise Received mpd May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 11ms May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 9ms May 25 21:33:00 volumiorpi4 volumio[998]: info: ------------------------------ 8ms May 25 21:33:00 volumiorpi4 volumio[998]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 25 21:33:03 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43:3000 from 192.168.4.22 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 13 May 25 21:33:03 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to 192.168.4.43:3000 from 192.168.4.22 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 May 25 21:33:03 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 25 21:33:03 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 25 21:33:03 volumiorpi4 volumio[998]: info: Discovery: Getting this device information May 25 21:33:03 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:33:03 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:03 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 25 21:33:03 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 25 21:33:05 volumiorpi4 systemd[1]: systemd-timedated.service: Succeeded. May 25 21:33:06 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 25 21:33:06 volumiorpi4 volumio[998]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 May 25 21:33:06 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetState May 25 21:33:06 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:07 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioPlay May 25 21:33:07 volumiorpi4 volumio[998]: info: CoreStateMachine::play index undefined May 25 21:33:07 volumiorpi4 volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined May 25 21:33:07 volumiorpi4 volumio[998]: info: CorePlayQueue::getTrack 0 May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 21:33:10 volumiorpi4 volumio-remote-updater[597]: No test mode May 25 21:33:10 volumiorpi4 volumio-remote-updater[597]: No alpha test mode May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetQueue May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreStateMachine::getQueue May 25 21:33:10 volumiorpi4 volumio[998]: info: CorePlayQueue::getQueue May 25 21:33:10 volumiorpi4 volumio[998]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} May 25 21:33:10 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumioGetBrowseSources May 25 21:33:11 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 21:33:12 volumiorpi4 volumio[998]: error: MyVolumio Plugin failed to authenticate in a timely fashion May 25 21:33:12 volumiorpi4 volumio[998]: info: Completed starting MyVolumio Plugin May 25 21:33:12 volumiorpi4 volumio[998]: [Metrics] CommandRouter: 37s 679.98ms May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::volumiosetStartupVolume May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::Close All Modals sent May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::Close All Modals sent May 25 21:33:12 volumiorpi4 volumio[998]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav May 25 21:33:12 volumiorpi4 volumio[998]: aplay: main:828: audio open error: Device or resource busy May 25 21:33:12 volumiorpi4 volumio[998]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 25 21:33:12 volumiorpi4 volumio[998]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 25 21:33:12 volumiorpi4 volumio[998]: TypeError: Cannot read property 'length' of undefined May 25 21:33:12 volumiorpi4 volumio[998]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 May 25 21:33:12 volumiorpi4 volumio[998]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 May 25 21:33:12 volumiorpi4 volumio[998]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) May 25 21:33:12 volumiorpi4 volumio[998]: at Parser.emit (events.js:315:20) May 25 21:33:12 volumiorpi4 volumio[998]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) May 25 21:33:12 volumiorpi4 volumio[998]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) May 25 21:33:12 volumiorpi4 volumio[998]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) May 25 21:33:12 volumiorpi4 volumio[998]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) May 25 21:33:12 volumiorpi4 volumio[998]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) May 25 21:33:12 volumiorpi4 volumio[998]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) May 25 21:33:12 volumiorpi4 volumio[998]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) May 25 21:33:12 volumiorpi4 volumio[998]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) May 25 21:33:12 volumiorpi4 volumio[998]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) May 25 21:33:12 volumiorpi4 volumio[998]: at IncomingMessage.emit (events.js:327:22) May 25 21:33:12 volumiorpi4 volumio[998]: at endReadableNT (internal/streams/readable.js:1327:12) May 25 21:33:12 volumiorpi4 volumio[998]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 25 21:33:12 volumiorpi4 volumio[998]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 25 21:33:13 volumiorpi4 sudo[1883]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-25 21:32 May 25 21:33:13 volumiorpi4 sudo[1883]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"