-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Fri 2026-10-16 17:26:58 CEST. -- Oct 16 17:25:59 klwurlitzer systemd-timedated[1028]: Changed local time to Fri Oct 16 17:25:59 2026 Oct 16 17:25:59 klwurlitzer sudo[1026]: pam_unix(sudo:session): session closed for user root Oct 16 17:25:59 klwurlitzer volumio-time-update[580]: volumio-time-update-util: System time updated successfully. Oct 16 17:25:59 klwurlitzer systemd[1]: Starting Daily apt download activities... Oct 16 17:25:59 klwurlitzer systemd[1]: Started Volumio Time Update Utility. Oct 16 17:25:59 klwurlitzer wireless.js[587]: trying... Oct 16 17:25:59 klwurlitzer sudo[1035]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 16 17:25:59 klwurlitzer sudo[1035]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:25:59 klwurlitzer sudo[1035]: pam_unix(sudo:session): session closed for user root Oct 16 17:25:59 klwurlitzer ntpd[831]: Listen normally on 3 eth0 192.168.1.254:123 Oct 16 17:25:59 klwurlitzer ntpd[831]: new interface(s) found: waking up resolver Oct 16 17:25:59 klwurlitzer nmbd[782]: [2026/10/16 17:25:59.923581, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 16 17:25:59 klwurlitzer systemd[1]: Started Samba NMB Daemon. Oct 16 17:25:59 klwurlitzer nmbd[782]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Oct 16 17:25:59 klwurlitzer dhcpcd[902]: eth0: leased 192.168.1.254 for 86400 seconds Oct 16 17:25:59 klwurlitzer dhcpcd[902]: eth0: adding route to 192.168.1.0/24 Oct 16 17:26:00 klwurlitzer systemd[1]: Starting Samba Winbind Daemon... Oct 16 17:25:59 klwurlitzer dhcpcd[902]: eth0: adding default route via 192.168.1.1 Oct 16 17:25:59 klwurlitzer dhcpcd[902]: forked to background, child pid 1076 Oct 16 17:26:00 klwurlitzer sudo[901]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:00 klwurlitzer wireless.js[587]: trying... Oct 16 17:26:00 klwurlitzer sudo[1078]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 16 17:26:00 klwurlitzer sudo[1078]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:00 klwurlitzer sudo[1078]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:00 klwurlitzer winbindd[1053]: [2026/10/16 17:26:00.295317, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Oct 16 17:26:00 klwurlitzer winbindd[1053]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Oct 16 17:26:00 klwurlitzer winbindd[1053]: [2026/10/16 17:26:00.310034, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 16 17:26:00 klwurlitzer systemd[1]: Started Samba Winbind Daemon. Oct 16 17:26:00 klwurlitzer winbindd[1053]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Oct 16 17:26:00 klwurlitzer systemd[1]: Starting Samba SMB Daemon... Oct 16 17:26:00 klwurlitzer smbd[1083]: [2026/10/16 17:26:00.676993, 0] ../lib/util/become_daemon.c:138(daemon_ready) Oct 16 17:26:00 klwurlitzer systemd[1]: Started Samba SMB Daemon. Oct 16 17:26:00 klwurlitzer smbd[1083]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Oct 16 17:26:01 klwurlitzer systemd[1]: apt-daily.service: Succeeded. Oct 16 17:26:01 klwurlitzer systemd[1]: Started Daily apt download activities. Oct 16 17:26:01 klwurlitzer systemd[1]: Starting Daily apt upgrade and clean activities... Oct 16 17:26:01 klwurlitzer wireless.js[587]: trying... Oct 16 17:26:01 klwurlitzer sudo[1125]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 16 17:26:01 klwurlitzer sudo[1125]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:01 klwurlitzer sudo[1125]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:01 klwurlitzer dhcpcd[1076]: wlan0: leased 192.168.20.6 for 86400 seconds Oct 16 17:26:01 klwurlitzer avahi-daemon[605]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.20.6. Oct 16 17:26:01 klwurlitzer avahi-daemon[605]: New relevant interface wlan0.IPv4 for mDNS. Oct 16 17:26:01 klwurlitzer dhcpcd[1076]: wlan0: adding route to 192.168.20.0/24 Oct 16 17:26:01 klwurlitzer avahi-daemon[605]: Registering new address record for 192.168.20.6 on wlan0.IPv4. Oct 16 17:26:01 klwurlitzer dhcpcd[1076]: wlan0: adding default route via 192.168.20.1 Oct 16 17:26:02 klwurlitzer wireless.js[587]: trying... Oct 16 17:26:02 klwurlitzer systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 16 17:26:02 klwurlitzer systemd[1]: Started Daily apt upgrade and clean activities. Oct 16 17:26:02 klwurlitzer sudo[1193]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 16 17:26:02 klwurlitzer sudo[1193]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:02 klwurlitzer sudo[1193]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:02 klwurlitzer wireless.js[587]: Connected to: ----FZ1 Oct 16 17:26:02 klwurlitzer wireless.js[587]: ---- Oct 16 17:26:02 klwurlitzer sudo[1196]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 16 17:26:02 klwurlitzer sudo[1196]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:02 klwurlitzer sudo[1196]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:02 klwurlitzer wireless.js[587]: ... joined AP, wlan0 IPv4 is 192.168.20.6, ipV6 is undefined Oct 16 17:26:02 klwurlitzer wireless.js[587]: It's done! AP Oct 16 17:26:02 klwurlitzer kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 16 17:26:02 klwurlitzer systemd[1]: Started Wireless Services. Oct 16 17:26:02 klwurlitzer systemd[1]: Started Volumio Backend Module. Oct 16 17:26:02 klwurlitzer systemd[1]: Started Volumio Cpu Tweaker. Oct 16 17:26:02 klwurlitzer systemd[1]: Reached target Multi-User System. Oct 16 17:26:02 klwurlitzer systemd[1]: Reached target Graphical Interface. Oct 16 17:26:02 klwurlitzer systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 16 17:26:02 klwurlitzer systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 16 17:26:02 klwurlitzer systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 16 17:26:02 klwurlitzer systemd[1]: Startup finished in 12.315s (kernel) + 23.031s (userspace) = 35.347s. Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: Setting RT Priority for mpd Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: pid 35's current scheduling policy: SCHED_OTHER Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: pid 35's current scheduling priority: 0 Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: Setting MPD Affinity Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: pid 3's current affinity mask: f Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Oct 16 17:26:02 klwurlitzer volumio-cpu-tweak[1202]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Oct 16 17:26:02 klwurlitzer systemd[1]: volumio_cpu_tweak.service: Succeeded. Oct 16 17:26:03 klwurlitzer ntpd[831]: Listen normally on 4 wlan0 192.168.20.6:123 Oct 16 17:26:03 klwurlitzer ntpd[831]: new interface(s) found: waking up resolver Oct 16 17:26:03 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:03 klwurlitzer volumio[1201]: info: ----- Volumio3 ---- Oct 16 17:26:03 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:03 klwurlitzer volumio[1201]: info: ----- System startup ---- Oct 16 17:26:03 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:04 klwurlitzer volumio[1201]: info: MYVOLUMIO Environment detected Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Plugin folders cleanup Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning into folder /volumio/app/plugins/ Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category audio_interface Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category miscellanea Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category music_service Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category plugins.json Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category system_controller Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category user_interface Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning into folder /data/plugins/ Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category audio_interface Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category music_service Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category system_controller Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category system_hardware Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Scanning category user_interface Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Plugin folders cleanup completed Oct 16 17:26:04 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:04 klwurlitzer volumio[1201]: info: ----- Core plugins startup ---- Oct 16 17:26:04 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Loading plugins from folder /volumio/app/plugins/ Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Adding plugin upnp to MyMusic Plugins Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Loading plugins from folder /data/plugins/ Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Loading plugin "system"... Oct 16 17:26:04 klwurlitzer volumio[1201]: info: Loading plugin "appearance"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "network"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Refreshing Cached IP Addresses Oct 16 17:26:05 klwurlitzer sudo[1233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 16 17:26:05 klwurlitzer sudo[1233]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:05 klwurlitzer sudo[1233]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:05 klwurlitzer sudo[1235]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 16 17:26:05 klwurlitzer sudo[1235]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:05 klwurlitzer sudo[1235]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "services"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "volumio5onboarding"... Oct 16 17:26:05 klwurlitzer sudo[1244]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 16 17:26:05 klwurlitzer sudo[1244]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "alsa_controller"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "wizard"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Loading plugin "networkfs"... Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Starting Udev Watcher for removable devices Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Ignoring mount for partition: boot Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Ignoring mount for partition: volumio Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Ignoring mount for partition: volumio_data Oct 16 17:26:05 klwurlitzer volumio[1201]: info: Mounting Device Extreme_SSD Oct 16 17:26:05 klwurlitzer sudo[1262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Extreme_SSD -o noatime Oct 16 17:26:05 klwurlitzer sudo[1262]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:06 klwurlitzer volumio-remote-updater[594]: [2026-10-16 17:26:06] [connect] Successful connection Oct 16 17:26:06 klwurlitzer mount.exfat[1264]: volume was not unmounted cleanly Oct 16 17:26:06 klwurlitzer sudo[1262]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:06 klwurlitzer volumio[1201]: WARN: volume was not unmounted cleanly. Oct 16 17:26:06 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "volumio_command_line_client"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Plugin upnp is not enabled Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "my_music"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "mpd"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "upnp_browser"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Starting UPNP Browser Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "alarm-clock"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Plugin airplay_emulation is not enabled Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "last_100"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "webradio"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "i2s_dacs"... Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "volumiodiscovery"... Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** For more information see Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 16 17:26:06 klwurlitzer volumio[1201]: *** WARNING *** For more information see Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** For more information see Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 16 17:26:06 klwurlitzer node[1201]: *** WARNING *** For more information see Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Discovery: Started advertising with name: KlWurlitzer Oct 16 17:26:06 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 16 17:26:06 klwurlitzer volumio[1201]: info: Loading plugin "bandcamp"... Oct 16 17:26:07 klwurlitzer volumio[1201]: info: Plugin youtube2 is not enabled Oct 16 17:26:07 klwurlitzer volumio[1201]: info: Loading plugin "autostart"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Applying required configuration parameters for plugin autostart Oct 16 17:26:08 klwurlitzer volumio[1201]: info: AutoStart - onVolumioStart - read config.json Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "outputs"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "albumart"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin example_plugin is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "inputs"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "updater_comm"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin mpdemulation is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "rest_api"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "websocket"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Starting Socket.io Server version 2.3.0 Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin fusiondsp is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin motherearthradio is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin backup_restore is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: Forking 3 albumart workers Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Plugin ir_controller is not enabled Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "music_services_shield"... Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Applying required configuration parameters for plugin music_services_shield Oct 16 17:26:08 klwurlitzer volumio[1201]: info: Loading plugin "Systeminfo"... Oct 16 17:26:08 klwurlitzer sudo[1244]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Loading i18n strings for locale de Oct 16 17:26:09 klwurlitzer volumio[1201]: Updating browse sources language Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:09 klwurlitzer volumio[1201]: Starting albumart workers Oct 16 17:26:09 klwurlitzer volumio[1201]: Starting albumart workers Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::initPlayerControls Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: Express server listening on port 3000 Oct 16 17:26:09 klwurlitzer volumio[1201]: [Metrics] WebUI: 6s 49.20ms Oct 16 17:26:09 klwurlitzer volumio[1201]: Starting albumart workers Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::resetVolumioState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::getcurrentVolume Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioRetrievevolume Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Volumio Network Manager: Network status updated: 3 Oct 16 17:26:09 klwurlitzer volumio-remote-updater[594]: [2026-10-16 17:26:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1792164366 101 Oct 16 17:26:09 klwurlitzer volumio[1201]: 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: 1 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::updateTrackBlock Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrackBlock Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioRetrievevolume Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Reloading queue from file Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Setting Device type: Raspberry PI Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::setRepeat false single undefined Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::setRandom false Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Completed loading Core Plugins Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Preparing to generate the ALSA configuration file Oct 16 17:26:09 klwurlitzer volumio[1201]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 16 17:26:09 klwurlitzer volumio[1201]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 16 17:26:09 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to 192.168.20.6:3000 from 192.168.20.88 UA: Dart/3.13 (dart:io) Engine version: 3 Transport: websocket Total Clients: 2 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Asound.conf file unchanged, so no further update is needed Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Output device has changed, restarting MPD Oct 16 17:26:09 klwurlitzer sudo[1343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 16 17:26:09 klwurlitzer sudo[1343]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:09 klwurlitzer volumio[1201]: info: ___________ START PLUGINS ___________ Oct 16 17:26:09 klwurlitzer sudo[1343]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:09 klwurlitzer sudo[1345]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 16 17:26:09 klwurlitzer sudo[1345]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:09 klwurlitzer volumio[1201]: info: ControllerMpd::onStart: Initializing MPD Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Creating MPD Configuration file Oct 16 17:26:09 klwurlitzer systemd[1]: musicservicesshield.service: Succeeded. Oct 16 17:26:09 klwurlitzer systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Oct 16 17:26:09 klwurlitzer systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Oct 16 17:26:09 klwurlitzer sudo[1349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Oct 16 17:26:09 klwurlitzer sudo[1349]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:09 klwurlitzer sudo[1353]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 16 17:26:09 klwurlitzer volumio[1201]: info: [1792164369955] CoreMusicLibrary::Adding element Medienserver Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:09 klwurlitzer volumio[1201]: info: UPNP Browser: Client initialized successfully Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 16 17:26:09 klwurlitzer volumio[1201]: info: [1792164369976] CoreMusicLibrary::Adding element Last_100 Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 16 17:26:09 klwurlitzer volumio[1201]: info: [1792164369978] CoreMusicLibrary::Adding element Webradio Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:09 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:09 klwurlitzer volumio[1201]: info: Initializing BBC Radios Oct 16 17:26:09 klwurlitzer sudo[1353]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:09 klwurlitzer sudo[1353]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:09 klwurlitzer sudo[1355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 16 17:26:09 klwurlitzer sudo[1355]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:09 klwurlitzer systemd[1]: Listening on mpd.socket. Oct 16 17:26:09 klwurlitzer systemd[1]: Starting Music Player Daemon... Oct 16 17:26:10 klwurlitzer systemd[1]: Started Volumio5 Onboarding Server. Oct 16 17:26:10 klwurlitzer systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 16 17:26:10 klwurlitzer systemd[1]: mpd.service: Succeeded. Oct 16 17:26:10 klwurlitzer systemd[1]: Stopped Music Player Daemon. Oct 16 17:26:10 klwurlitzer sudo[1349]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:10 klwurlitzer systemd[1]: Starting Music Player Daemon... Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 16 17:26:10 klwurlitzer volumio[1201]: info: [1792164370078] CoreMusicLibrary::Adding element Bandcamp Discover Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:10 klwurlitzer volumio[1201]: Cannot find translation for source Bandcamp Discover Oct 16 17:26:10 klwurlitzer volumio[1201]: info: AutoStart - onStart Oct 16 17:26:10 klwurlitzer sudo[1370]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 16 17:26:10 klwurlitzer sudo[1370]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:10 klwurlitzer sudo[1370]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 16 17:26:10 klwurlitzer sudo[1370]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Volumio Calling Home Oct 16 17:26:10 klwurlitzer sudo[1404]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Oct 16 17:26:10 klwurlitzer sudo[1404]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: adding 294591d5-8320-4da3-aa68-a08910ca0ed2 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Found device KlWurlitzer Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: this is already registered, 294591d5-8320-4da3-aa68-a08910ca0ed2 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Found device KlWurlitzer Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 16 17:26:10 klwurlitzer volumio[1201]: info: MPD Permissions set Oct 16 17:26:10 klwurlitzer volumio[1201]: info: MPD Permissions set Oct 16 17:26:10 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Volumio called home Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:10 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to 192.168.20.6:3000 from 192.168.20.88 UA: Dart/3.13 (dart:io) Engine version: 3 Transport: websocket Total Clients: 3 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:10 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:10.619+02:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Oct 16 17:26:10 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Oct 16 17:26:10 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:10 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:10.728+02:00 level=INFO msg="system info for ccb89058b12a34f0379b80c8c6938a11" deviceName=KlWurlitzer deviceVariant=volumio deviceModel= softwareVersion=3.912 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 16 17:26:10 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:10.743+02:00 level=INFO msg="enabling local network discovery" Oct 16 17:26:10 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:10.757+02:00 level=INFO msg="enabling BLE discovery" Oct 16 17:26:10 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:10.831+02:00 level=INFO msg="bootstrapping state" hasInternet=true Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:10 klwurlitzer volumio-remote-updater[594]: No test mode Oct 16 17:26:10 klwurlitzer volumio-remote-updater[594]: No alpha test mode Oct 16 17:26:10 klwurlitzer sudo[1404]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:10 klwurlitzer sudo[1439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Oct 16 17:26:10 klwurlitzer sudo[1439]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:10 klwurlitzer volumio[1201]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:10 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.419+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.20.88:39682 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.432+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.20.88:56156 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.440+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.20.88:39682 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.440+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.20.88:39682 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.446+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.20.88:39700 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.452+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.20.88:56156 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.453+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.20.88:56156 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.463+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.20.88:56174 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.766+02:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.802+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.20.88:39700 @ 0x33de870" latency=-1.516686406s platform=PLATFORM_ANDROID version=6.261014.0 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.802+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.20.88:39700 @ 0x33de870" latency=-1.518425742s timeout=20s Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.802+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 16 17:26:11 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:11 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.810+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" name=KlWurlitzer Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:11 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.815+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" language=de Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.820+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" timezone=Europe/Berlin Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.823+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" available=true connected=true macAddress=d8:3a:dd:28:0b:5c ip4Address=192.168.1.254/24 ip6Address= Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.829+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" available=true connected=true macAddress=d8:3a:dd:28:0b:5d ip4Address=192.168.20.6/24 ip6Address= ssid=FZ1 Oct 16 17:26:11 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:11.830+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" setupComplete=true Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 16 17:26:11 klwurlitzer volumio[1201]: amixer -c 1 info | grep "bcm2835 ALSA" Oct 16 17:26:11 klwurlitzer volumio[1201]: amixer -c 2 info | grep "bcm2835 Headphones" Oct 16 17:26:11 klwurlitzer volumio[1201]: Card hw:2 'Headphones'/'bcm2835 Headphones' Oct 16 17:26:11 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableLanguages Oct 16 17:26:12 klwurlitzer volumio[1201]: amixer -c 0 info | grep "snd_rpi_rpi_dac" Oct 16 17:26:12 klwurlitzer volumio[1201]: Card hw:0 'sndrpirpidac'/'snd_rpi_rpi_dac' Oct 16 17:26:12 klwurlitzer volumio[1201]: amixer -c 0 info | grep "R-PI DAC" Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.093+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" selectedOutputId=0 Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Oct 16 17:26:12 klwurlitzer mpd[1378]: Oct 16 17:26 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 16 17:26:12 klwurlitzer sudo[1471]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Oct 16 17:26:12 klwurlitzer sudo[1471]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer sudo[1477]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 16 17:26:12 klwurlitzer sudo[1477]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer sudo[1477]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1483]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 16 17:26:12 klwurlitzer sudo[1471]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1483]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer sudo[1483]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1488]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Oct 16 17:26:12 klwurlitzer sudo[1488]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer sudo[1488]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1497]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 16 17:26:12 klwurlitzer sudo[1497]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:12 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.213+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" currentVersion=3.912 latestVersion=3.912 Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.213+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.20.88:39700 @ 0x33de870" status=UPDATE_STATUS_NONE progress=0 Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.214+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" userId= Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.214+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" providers=3 Oct 16 17:26:12 klwurlitzer sudo[1497]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1499]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:12 klwurlitzer sudo[1499]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.226+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" plugins=0 Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:12 klwurlitzer sudo[1499]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.234+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" state=STATUS_STOPPED positionMs=0 volume=100 Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.234+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.20.88:39700 @ 0x33de870" id=qobuz://song/303579393 title="Wieder auf der Straße" Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:12 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.262+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517372031s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 16 17:26:12 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.275+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s Oct 16 17:26:12 klwurlitzer systemd[1]: systemd-fsckd.service: Succeeded. Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.485+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=http://pushupdates.volumio.org duration=207.640738ms Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.499+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=http://cddb.volumio.org duration=223.466293ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 16 17:26:12 klwurlitzer systemd[1]: Started Music Player Daemon. Oct 16 17:26:12 klwurlitzer sudo[1345]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer sudo[1355]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:12 klwurlitzer systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.653+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=377.638741ms Oct 16 17:26:12 klwurlitzer volumio[1201]: info: Completed starting Core Plugins Oct 16 17:26:12 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:12 klwurlitzer volumio[1201]: info: ----- MyVolumio plugins startup ---- Oct 16 17:26:12 klwurlitzer volumio[1201]: info: ------------------------------------------- Oct 16 17:26:12 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 16 17:26:12 klwurlitzer volumio[1201]: error: MPD error: The expression evaluated to a falsy value: Oct 16 17:26:12 klwurlitzer volumio[1201]: assert.ok(self.idling) Oct 16 17:26:12 klwurlitzer volumio[1201]: error: The expression evaluated to a falsy value: Oct 16 17:26:12 klwurlitzer volumio[1201]: assert.ok(self.idling) Oct 16 17:26:12 klwurlitzer volumio[1201]: error: updateQueue error: null Oct 16 17:26:12 klwurlitzer volumio[1201]: info: MPD running with PID1378 Oct 16 17:26:12 klwurlitzer volumio[1201]: ,establishing connection Oct 16 17:26:12 klwurlitzer volumio[1201]: error: updateQueue error: null Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.815+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://myvolumio.firebaseio.com duration=537.790279ms Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.872+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=http://plugins.volumio.org duration=593.915164ms Oct 16 17:26:12 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:12.996+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://www.googleapis.com duration=720.4196ms Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.022+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=744.085145ms Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.030+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=750.82767ms Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.096+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://functions.volumio.cloud duration=819.023157ms Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.100+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://functions.volumio.cloud duration=821.927601ms Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.111+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://securetoken.googleapis.com duration=835.505925ms Oct 16 17:26:13 klwurlitzer volumio[1514]: cset: --> shielding system active with Oct 16 17:26:13 klwurlitzer volumio[1514]: cset: "system" cpuset of CPUSPEC(1-3) with 121 tasks running Oct 16 17:26:13 klwurlitzer volumio[1514]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Oct 16 17:26:13 klwurlitzer systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Oct 16 17:26:13 klwurlitzer systemd[1]: Reloading. Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.305+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://database.volumio.cloud duration=1.026087588s Oct 16 17:26:13 klwurlitzer sudo[1546]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 16 17:26:13 klwurlitzer sudo[1546]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:13 klwurlitzer sudo[1546]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:13 klwurlitzer sudo[1548]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 16 17:26:13 klwurlitzer sudo[1548]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:13 klwurlitzer sudo[1548]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:13 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:13.360+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" latency=-1.517256442s timeout=10s endpoint=https://google.com duration=1.084687904s Oct 16 17:26:13 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.20.88 UA: Mozilla/5.0 (Linux; Android 17; Pixel 11 Pro Build/CD1A.260905.001.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.261014.0 Engine version: 3 Transport: polling Total Clients: 4 Oct 16 17:26:13 klwurlitzer 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. Oct 16 17:26:13 klwurlitzer sudo[1552]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 16 17:26:13 klwurlitzer sudo[1552]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:13 klwurlitzer sudo[1552]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:13 klwurlitzer sudo[1554]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 16 17:26:13 klwurlitzer sudo[1554]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:13 klwurlitzer sudo[1554]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:13 klwurlitzer systemd[1]: getty@tty1.service: Current command vanished from the unit file, execution of the command list won't be resumed. Oct 16 17:26:13 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.20.88 UA: Mozilla/5.0 (Linux; Android 17; Pixel 11 Pro Build/CD1A.260905.001.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.261014.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetVisibleSources Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 16 17:26:13 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:13 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:13 klwurlitzer volumio[1201]: info: Listing playlists Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 16 17:26:13 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 16 17:26:13 klwurlitzer sudo[1439]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:13 klwurlitzer volumio[1201]: info: succeeded Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:15 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:15 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:15 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 17:26:16 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:16 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:16 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:17 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Oct 16 17:26:21 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetQueue Oct 16 17:26:21 klwurlitzer volumio[1201]: info: CoreStateMachine::getQueue Oct 16 17:26:21 klwurlitzer volumio[1201]: info: CorePlayQueue::getQueue Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin bluetooth to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin multiroom to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin metavolumio to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin cd_controller to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 16 17:26:22 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 16 17:26:23 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 16 17:26:23 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 16 17:26:23 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:23 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:23 klwurlitzer volumio[1201]: info: Starting MyVolumio Remote Streaming Endpoints Oct 16 17:26:23 klwurlitzer volumio[1201]: info: MyVolumio login type: Token Oct 16 17:26:23 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 16 17:26:23 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 16 17:26:24 klwurlitzer volumio[1201]: info: Starting Streaming Service Transparent Proxy Oct 16 17:26:24 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 16 17:26:24 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 16 17:26:24 klwurlitzer volumio[1201]: info: Streaming services startup Oct 16 17:26:24 klwurlitzer volumio[1201]: info: Starting Streaming Daemon Oct 16 17:26:24 klwurlitzer sudo[1578]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 16 17:26:24 klwurlitzer sudo[1578]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:24 klwurlitzer sudo[1578]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:24 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 16 17:26:24 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 16 17:26:24 klwurlitzer volumio[1201]: error: Cannot start Volumio Streaming Daemon Oct 16 17:26:24 klwurlitzer volumio[1201]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 16 17:26:24 klwurlitzer volumio[1201]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 16 17:26:24 klwurlitzer volumio[1201]: STREAMING PROXY: Starting server on port 3245 Oct 16 17:26:24 klwurlitzer volumio[1201]: Node JS runtime: 14 Oct 16 17:26:25 klwurlitzer volumio[1201]: error: MyVolumio Custom Token format not valid, refreshing it Oct 16 17:26:26 klwurlitzer volumio[1201]: Searching plugin music_service/qobuz Oct 16 17:26:26 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Oct 16 17:26:26 klwurlitzer volumio[1201]: info: All search sources collected, pushing search results Oct 16 17:26:26 klwurlitzer volumio[1201]: info: MyVolumio login type: Token Oct 16 17:26:27 klwurlitzer volumio[1201]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 16 17:26:27 klwurlitzer volumio[1201]: Searching plugin music_service/qobuz Oct 16 17:26:27 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Oct 16 17:26:27 klwurlitzer volumio[1201]: info: All search sources collected, pushing search results Oct 16 17:26:27 klwurlitzer volumio[1201]: Searching plugin music_service/qobuz Oct 16 17:26:27 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Oct 16 17:26:27 klwurlitzer volumio[1201]: info: All search sources collected, pushing search results Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MyVolumio token set successfully Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MYVOLUMIO: Adding device Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MYVOLUMIO: Evaluating Server Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MyVolumio Plan changed: premium Oct 16 17:26:28 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Removing browser output: myVolumio user plan is not superstar Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Removing audio output: Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MYVOLUMIO: Adding device Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MYVOLUMIO: Evaluating Server Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Remote config written successfully Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Starting Tunnel 1 Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Starting Tunnel Connection Checker Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Completed starting MyVolumio Plugin Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MYVolumio Device enabled Oct 16 17:26:28 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Oct 16 17:26:28 klwurlitzer volumio[1201]: info: MyVolumio status changed Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Streaming services startup Oct 16 17:26:28 klwurlitzer volumio[1201]: info: Starting Streaming Daemon Oct 16 17:26:29 klwurlitzer sudo[1638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 16 17:26:29 klwurlitzer sudo[1638]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:29 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Oct 16 17:26:29 klwurlitzer volumio[1201]: error: [MyVolumio PluginManager] Cache data is invalid! Oct 16 17:26:29 klwurlitzer systemd[1]: systemd-timedated.service: Succeeded. Oct 16 17:26:29 klwurlitzer sudo[1638]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:29 klwurlitzer volumio[1201]: error: Cannot start Volumio Streaming Daemon Oct 16 17:26:29 klwurlitzer volumio[1201]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 16 17:26:29 klwurlitzer volumio[1201]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 16 17:26:29 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Oct 16 17:26:29 klwurlitzer volumio[1201]: info: [1792164389897] Starting BluetoothController Oct 16 17:26:29 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Oct 16 17:26:31 klwurlitzer sudo[1643]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Oct 16 17:26:31 klwurlitzer sudo[1643]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer sudo[1643]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: MultiRoom plugin initialized Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: STOPPING SNAPCLIENT Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: Snap server stop Oct 16 17:26:31 klwurlitzer sudo[1659]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Oct 16 17:26:31 klwurlitzer sudo[1659]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: STOPPING volumioStreaming Oct 16 17:26:31 klwurlitzer sudo[1661]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Oct 16 17:26:31 klwurlitzer sudo[1661]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer sudo[1659]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer sudo[1665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Oct 16 17:26:31 klwurlitzer sudo[1665]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer sudo[1661]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer sudo[1668]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Oct 16 17:26:31 klwurlitzer sudo[1668]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Oct 16 17:26:31 klwurlitzer sudo[1665]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer sudo[1668]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Preparing to generate the ALSA configuration file Oct 16 17:26:31 klwurlitzer volumio[1201]: info: AutoStart - Plugin is starting Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetQueue Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::getQueue Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CorePlayQueue::getQueue Oct 16 17:26:31 klwurlitzer volumio[1201]: info: AutoStart - start playing Oct 16 17:26:31 klwurlitzer volumio[1201]: info: AutoStart - start playing from position 5 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPlay Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::play index 5 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::stop Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::play index undefined Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreStateMachine::startPlaybackTimer Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [1792164391516] ControllerQobuz::clearAddPlayTrack Oct 16 17:26:31 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand stop Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Setting Geolocation for MyVolumio to eu6 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Setting Geolocation for MyVolumio to eu4 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: sendMpdCommand stop took 33 milliseconds Oct 16 17:26:31 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand clear Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: Removed streaming files Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: volumioStreaming STOPPED Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: SNAPSERVER STOPPED Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: SNAPCLIENT STOPPED Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Oct 16 17:26:31 klwurlitzer volumio[1201]: ---------------------------- MPD announces system playlist update Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Ignoring MPD Status Update Oct 16 17:26:31 klwurlitzer volumio[1201]: info: sendMpdCommand clear took 12 milliseconds Oct 16 17:26:31 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/303579398" Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Oct 16 17:26:31 klwurlitzer volumio[1201]: ---------------------------- MPD announces system playlist update Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Ignoring MPD Status Update Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Oct 16 17:26:31 klwurlitzer volumio[1201]: ---------------------------- MPD announces system playlist update Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Ignoring MPD Status Update Oct 16 17:26:31 klwurlitzer volumio[1201]: error: updateQueue error: null Oct 16 17:26:31 klwurlitzer volumio[1201]: info: ------------------------------ 7ms Oct 16 17:26:31 klwurlitzer volumio[1201]: STREAMING PROXY: Handling url /?data=qobuz://song/303579398 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Asound.conf file unchanged, so no further update is needed Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Output device has changed, restarting MPD Oct 16 17:26:31 klwurlitzer sudo[1671]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 16 17:26:31 klwurlitzer sudo[1671]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer sudo[1671]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer sudo[1674]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 16 17:26:31 klwurlitzer sudo[1674]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 16 17:26:31 klwurlitzer systemd[1]: musicservicesshield.service: Succeeded. Oct 16 17:26:31 klwurlitzer systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Oct 16 17:26:31 klwurlitzer systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Oct 16 17:26:31 klwurlitzer systemd[1]: Stopping Music Player Daemon... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Plugin multiroom disabled by user. Not starting Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding METAVOLUMIO REST API Endpoints Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Plugin cd_controller disabled by user. Not starting Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding inputs REST Endpoints Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Scanning Audio Inputs Oct 16 17:26:31 klwurlitzer sudo[1679]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name KlWurlitzer Oct 16 17:26:31 klwurlitzer sudo[1679]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer sudo[1679]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Checking against Known Cards name Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding Server instance for streaming Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Oct 16 17:26:31 klwurlitzer volumio[1201]: error: Hi Res Audio Failed Login: Missing Login Data Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding HIGHRESAUDIO REST API Endpoints Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Refreshing QOBUZ token Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Plugin tidalconnect disabled by user. Not starting Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Oct 16 17:26:31 klwurlitzer volumio[1201]: info: QobuzConnect: Starting Qobuz Connect socket and service Oct 16 17:26:31 klwurlitzer volumio[1201]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding TIDAL REST API Endpoints Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Oct 16 17:26:31 klwurlitzer sudo[1687]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Oct 16 17:26:31 klwurlitzer sudo[1687]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Received Get System Version Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Received Get System Info Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 17:26:31 klwurlitzer sudo[1687]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Discovery: Getting this device information Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Bluetooth name changed to KlWurlitzer Oct 16 17:26:31 klwurlitzer volumio[1201]: info: MPD Permissions set Oct 16 17:26:31 klwurlitzer sudo[1689]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Oct 16 17:26:31 klwurlitzer sudo[1689]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:31 klwurlitzer volumio[1201]: info: No valid Plugin REST Endpoint: getStreamUrlqobuz Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: STREAMING PROXY: Error: Failed to retrieve proper real streamUrl: {"success":false,"error":"No valid Plugin REST Endpoint: getStreamUrlqobuz"} Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:31 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/303579398" Oct 16 17:26:31 klwurlitzer volumio[1201]: error: MPD error: Error: write EPIPE Oct 16 17:26:31 klwurlitzer volumio[1201]: error: write EPIPE {"errno":-32,"code":"EPIPE","syscall":"write"} Oct 16 17:26:31 klwurlitzer systemd[1]: Started Volumio Qobuz Connect Service. Oct 16 17:26:31 klwurlitzer sudo[1689]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Access Token successfully retrieved Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 16 17:26:31 klwurlitzer volumio[1201]: info: [1792164391964] CoreMusicLibrary::Adding element QOBUZ Oct 16 17:26:31 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 17:26:31 klwurlitzer volumio[1201]: Cannot find translation for source Bandcamp Discover Oct 16 17:26:31 klwurlitzer volumio[1201]: Cannot find translation for source QOBUZ Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Stopping AccessToken refresher cron for QOBUZ Oct 16 17:26:31 klwurlitzer systemd[1]: mpd.service: Succeeded. Oct 16 17:26:31 klwurlitzer systemd[1]: Stopped Music Player Daemon. Oct 16 17:26:31 klwurlitzer volumio[1201]: info: AccessToken refresher cron started for QOBUZ Oct 16 17:26:31 klwurlitzer systemd[1]: Starting Music Player Daemon... Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding QOBUZ REST API Endpoints Oct 16 17:26:31 klwurlitzer volumio[1201]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Oct 16 17:26:32 klwurlitzer volumio[1201]: [Metrics] CommandRouter: 28s 173.93ms Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumiosetStartupVolume Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:32 klwurlitzer volumio[1201]: info: VolumeController:: Setting startup Volume 100 Oct 16 17:26:32 klwurlitzer volumio[1201]: info: VolumeController::SetAlsaVolume100 Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::Close All Modals sent Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::Close All Modals sent Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:32 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:32.071+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" state=STATUS_STOPPED positionMs=283 volume=100 Oct 16 17:26:32 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:32.073+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" id=qobuz://song/303579398 title="Ich bin ein Stern" Oct 16 17:26:32 klwurlitzer sudo[1696]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 16 17:26:32 klwurlitzer sudo[1696]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Executing endpoint qc_getconfig Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Oct 16 17:26:32 klwurlitzer sudo[1696]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.118 [1691.1691] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Oct 16 17:26:32 klwurlitzer volumio[1201]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Oct 16 17:26:32 klwurlitzer volumio[1201]: info: QobuzConnect: QOBUZ Connect daemon connected Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Successfully Added MyVolumio device Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.200 [1691.1691] INFO VolumeManager: [0x9d35a0]: Setting new playback volume: 75 Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.200 [1691.1691] INFO VolumeManager: [0x9d35a0]: Setting new mute state: 0 Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.200 [1691.1691] INFO AudioStreamManager: [0x9d32f8]: Setting new audio download buffer size: 1048576 Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.200 [1691.1691] INFO QobuzConnect: [0x9d3e68]: Client initialized! Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.200 [1691.1691] INFO SampleApp: Starting Avahi advertising, name: KlWurlitzer, service name: _qobuz-connect._tcp Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.205 [1691.1691] INFO LocalConfigManager: [0x9d3020]: Starting Local Configuration server Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.205 [1691.1691] INFO SampleApp: Starting Local configuration server Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.205 [1691.1691] INFO SampleApp: Connected to UNIX socket client 0x9c8f60 Oct 16 17:26:32 klwurlitzer qobuz-connect[1691]: 20261016 17:26:32.269 [1691.1691] INFO SampleApp: Playback volume changed: 75 Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Successfully Added MyVolumio device Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Updating MyVolumio device info Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Updating MyVolumio device info Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:32 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:32 klwurlitzer mpd[1703]: Oct 16 17:26 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 16 17:26:32 klwurlitzer volumio[1201]: info: Successfully Updated MyVolumio device Oct 16 17:26:33 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 16 17:26:33 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 16 17:26:33 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 16 17:26:33 klwurlitzer systemd[1]: Started Music Player Daemon. Oct 16 17:26:33 klwurlitzer sudo[1674]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:33 klwurlitzer volumio[1201]: error: updateQueue error: null Oct 16 17:26:33 klwurlitzer systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Oct 16 17:26:33 klwurlitzer volumio[1201]: info: Successfully Updated MyVolumio device Oct 16 17:26:33 klwurlitzer volumio[1708]: cset: --> shielding system active with Oct 16 17:26:33 klwurlitzer volumio[1708]: cset: "system" cpuset of CPUSPEC(1-3) with 127 tasks running Oct 16 17:26:33 klwurlitzer volumio[1708]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Oct 16 17:26:33 klwurlitzer systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Oct 16 17:26:33 klwurlitzer sudo[1728]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Oct 16 17:26:33 klwurlitzer sudo[1728]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:33 klwurlitzer systemd[1]: Started MyVolumio SSH Tunnel. Oct 16 17:26:33 klwurlitzer sudo[1728]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:33 klwurlitzer volumio[1201]: info: Remote SSH Started Oct 16 17:26:33 klwurlitzer autossh[1731]: port set to 0, monitoring disabled Oct 16 17:26:33 klwurlitzer autossh[1731]: starting ssh (count 1) Oct 16 17:26:33 klwurlitzer autossh[1731]: ssh child pid is 1734 Oct 16 17:26:33 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 16 17:26:33 klwurlitzer volumiossh-tunnel[1730]: Warning: Permanently added '[eu4.myvolumio.org]:2222,[167.172.103.77]:2222' (RSA) to the list of known hosts. Oct 16 17:26:33 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:33 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:34 klwurlitzer sudo[1736]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Oct 16 17:26:34 klwurlitzer sudo[1736]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:34 klwurlitzer systemd[1]: Started Volumio Bluetooth Module. Oct 16 17:26:34 klwurlitzer sudo[1736]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:34 klwurlitzer volumio[1201]: info: Volumio BT Module successfully started Oct 16 17:26:34 klwurlitzer sudo[1739]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* Oct 16 17:26:34 klwurlitzer sudo[1739]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:34 klwurlitzer volumiobt[1738]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory Oct 16 17:26:34 klwurlitzer sudo[1739]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:35 klwurlitzer sudo[1755]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio Oct 16 17:26:35 klwurlitzer sudo[1755]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 17:26:35 klwurlitzer volumiobt[1738]: pulseaudio: no process found Oct 16 17:26:35 klwurlitzer sudo[1755]: pam_unix(sudo:session): session closed for user root Oct 16 17:26:35 klwurlitzer dbus-daemon[583]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.20' (uid=1000 pid=1760 comm="/usr/bin/pulseaudio --high-priority=true ") Oct 16 17:26:35 klwurlitzer systemd[1]: Starting RealtimeKit Scheduling Policy Service... Oct 16 17:26:35 klwurlitzer volumio[1201]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 16 17:26:36 klwurlitzer dbus-daemon[583]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' Oct 16 17:26:36 klwurlitzer systemd[1]: Started RealtimeKit Scheduling Policy Service. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Successfully called chroot. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Successfully dropped privileges. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Successfully limited resources. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Running. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Canary thread running. Oct 16 17:26:36 klwurlitzer rtkit-daemon[1761]: Watchdog thread running. Oct 16 17:26:36 klwurlitzer dbus-daemon[583]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.21' (uid=0 pid=1761 comm="/usr/lib/rtkit/rtkit-daemon ") Oct 16 17:26:36 klwurlitzer systemd[1]: Starting Authorization Manager... Oct 16 17:26:36 klwurlitzer volumio[1201]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 16 17:26:36 klwurlitzer polkitd[1765]: started daemon version 0.105 using authority implementation `local' version `0.105' Oct 16 17:26:36 klwurlitzer dbus-daemon[583]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Oct 16 17:26:36 klwurlitzer systemd[1]: Started Authorization Manager. Oct 16 17:26:36 klwurlitzer pulseaudio[1760]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Oct 16 17:26:36 klwurlitzer pulseaudio[1760]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Oct 16 17:26:36 klwurlitzer pulseaudio[1760]: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Applying permissions Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Setting BT discoverable and pairable Oct 16 17:26:36 klwurlitzer bluetoothd[700]: Endpoint registered: sender=:1.41 path=/MediaEndpoint/A2DPSource Oct 16 17:26:36 klwurlitzer bluetoothd[700]: Endpoint registered: sender=:1.41 path=/MediaEndpoint/A2DPSink Oct 16 17:26:36 klwurlitzer kernel: Bluetooth: RFCOMM TTY layer initialized Oct 16 17:26:36 klwurlitzer kernel: Bluetooth: RFCOMM socket layer initialized Oct 16 17:26:36 klwurlitzer kernel: Bluetooth: RFCOMM ver 1.11 Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [96B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [77B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [77B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [79B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [95B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [33B blob data] Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> -e power on Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Invalid command in menu main: -e Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Use "help" for a list of available commands in a menu. Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Use "menu " if you want to enter any submenu. Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Use "back" if you want to return to menu main. Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> agent on Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Agent is already registered Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> discoverable on Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> pairable on Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> agent NoInputNoOutput Oct 16 17:26:36 klwurlitzer volumiobt[1738]: Agent is already registered Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> default-agent Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [bluetoothctl]> quit Oct 16 17:26:36 klwurlitzer volumiobt[1738]: [65B blob data] Oct 16 17:26:38 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 16 17:26:38 klwurlitzer volumio[1201]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 16 17:26:38 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:38 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 5 Oct 16 17:26:39 klwurlitzer volumio[1201]: info: BOOT COMPLETED Oct 16 17:26:40 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:40 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 17:26:40 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 16 17:26:40 klwurlitzer volumio-remote-updater[594]: No test mode Oct 16 17:26:40 klwurlitzer volumio-remote-updater[594]: No alpha test mode Oct 16 17:26:40 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 16 17:26:40 klwurlitzer volumio[1201]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 16 17:26:40 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 16 17:26:41 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Oct 16 17:26:41 klwurlitzer volumio[1201]: info: handleBrowseUri took 123 milliseconds Oct 16 17:26:41 klwurlitzer volumio[1201]: info: Preload queue cleared Oct 16 17:26:41 klwurlitzer volumio[1201]: info: Preload queue cleared Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetBrowseSources Oct 16 17:26:43 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 17:26:45 klwurlitzer volumio[1201]: Searching plugin music_service/qobuz Oct 16 17:26:45 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Oct 16 17:26:47 klwurlitzer volumio[1201]: info: searchQOBUZUri took 1149 milliseconds Oct 16 17:26:47 klwurlitzer volumio[1201]: info: All search sources collected, pushing search results Oct 16 17:26:47 klwurlitzer volumio[1201]: Searching plugin music_service/qobuz Oct 16 17:26:47 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , search Oct 16 17:26:48 klwurlitzer volumio[1201]: info: searchQOBUZUri took 1487 milliseconds Oct 16 17:26:48 klwurlitzer volumio[1201]: info: All search sources collected, pushing search results Oct 16 17:26:51 klwurlitzer volumio[1201]: info: Preload queue cleared Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreStateMachine::ClearQueue Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreStateMachine::stop Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CorePlayQueue::clearPlayQueue Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CorePlayQueue::saveQueue Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushQueue Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CoreStateMachine::addQueueItems Oct 16 17:26:51 klwurlitzer volumio[1201]: info: CorePlayQueue::addQueueItems Oct 16 17:26:51 klwurlitzer volumio[1201]: info: Preload queue cleared Oct 16 17:26:51 klwurlitzer volumio[1201]: info: Adding Item to queue: qobuz://artist/43821 Oct 16 17:26:51 klwurlitzer volumio[1201]: info: Exploding uri qobuz://artist/43821 in service qobuz Oct 16 17:26:51 klwurlitzer volumio[1201]: https://prod.vlmapi.io/v2/qobuz/explodeUri Oct 16 17:26:51 klwurlitzer ntpd[831]: Soliciting pool server 185.252.140.126 Oct 16 17:26:52 klwurlitzer ntpd[831]: Soliciting pool server 131.188.3.220 Oct 16 17:26:52 klwurlitzer ntpd[831]: Soliciting pool server 128.140.109.119 Oct 16 17:26:52 klwurlitzer ntpd[831]: Soliciting pool server 193.203.3.171 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: explodeUri took 1975 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushQueue Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CorePlayQueue::saveQueue Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::updateTrackBlock Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrackBlock Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPlay Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::play index 0 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::stop Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::play index undefined Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::startPlaybackTimer Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: [1792164413039] ControllerQobuz::clearAddPlayTrack Oct 16 17:26:53 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand stop Oct 16 17:26:53 klwurlitzer volumio[1201]: info: sendMpdCommand stop took 3 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand clear Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Oct 16 17:26:53 klwurlitzer volumio[1201]: ---------------------------- MPD announces system playlist update Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Ignoring MPD Status Update Oct 16 17:26:53 klwurlitzer volumio[1201]: info: sendMpdCommand clear took 1 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand load "http://127.0.0.1:3245?data=qobuz://song/427251968" Oct 16 17:26:53 klwurlitzer volumio[1201]: error: updateQueue error: null Oct 16 17:26:53 klwurlitzer volumio[1201]: info: ------------------------------ 2ms Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Handling url /?data=qobuz://song/427251968 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Executing endpoint getStreamUrlqobuz Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Oct 16 17:26:53 klwurlitzer ntpd[831]: Soliciting pool server 217.144.138.234 Oct 16 17:26:53 klwurlitzer ntpd[831]: Soliciting pool server 134.60.1.27 Oct 16 17:26:53 klwurlitzer ntpd[831]: Soliciting pool server 152.53.191.142 Oct 16 17:26:53 klwurlitzer ntpd[831]: Soliciting pool server 162.159.200.1 Oct 16 17:26:53 klwurlitzer ntpd[831]: Soliciting pool server 172.104.134.72 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: getStreamUrl took 395 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=2727708&eid=427251968&fmt=7&profile=raw&app_id=539451548&cid=1901965&etsp=1792168014&hmac=Tre0zY_AmpRuS1DWLuxh1qNcXqc Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Requesting upstream with range: none Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Upstream status code: 200 Oct 16 17:26:53 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/427251968" Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Oct 16 17:26:53 klwurlitzer volumio[1201]: ---------------------------- MPD announces system playlist update Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Ignoring MPD Status Update Oct 16 17:26:53 klwurlitzer volumio[1201]: info: sendMpdCommand add "http://127.0.0.1:3245?data=qobuz://song/427251968" took 1 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 16 17:26:53 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand play Oct 16 17:26:53 klwurlitzer volumio[1201]: info: ------------------------------ 2ms Oct 16 17:26:53 klwurlitzer volumio[1201]: info: sendMpdCommand play took 2 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Client closed connection Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Upstream closed. Received 38900 bytes Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Incomplete transfer. Expected 46121724, got 38900 Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Retrying with range: bytes=38900- (attempt 1) Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Handling url /?data=qobuz://song/427251968 Oct 16 17:26:53 klwurlitzer volumio[1201]: info: Executing endpoint getStreamUrlqobuz Oct 16 17:26:53 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , getStreamUrlAPI Oct 16 17:26:53 klwurlitzer volumio[1201]: info: getStreamUrl took 351 milliseconds Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Got real url: https://streaming-qobuz-std.akamaized.net/file?uid=2727708&eid=427251968&fmt=7&profile=raw&app_id=539451548&cid=1901965&etsp=1792168014&hmac=Tre0zY_AmpRuS1DWLuxh1qNcXqc Oct 16 17:26:53 klwurlitzer volumio[1201]: STREAMING PROXY: Requesting upstream with range: none Oct 16 17:26:54 klwurlitzer volumio[1201]: STREAMING PROXY: Upstream status code: 200 Oct 16 17:26:54 klwurlitzer volumio[1201]: info: Oct 16 17:26:54 klwurlitzer volumio[1201]: ---------------------------- MPD announces state update: player Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ControllerMpd::getState Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand status Oct 16 17:26:54 klwurlitzer volumio[1201]: info: Oct 16 17:26:54 klwurlitzer volumio[1201]: ---------------------------- MPD announces state update: player Oct 16 17:26:54 klwurlitzer volumio[1201]: info: sendMpdCommand status took 19 milliseconds Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ControllerMpd::getState Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand status Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::parseState Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 17:26:54 klwurlitzer volumio[1201]: info: sendMpdCommand status took 4 milliseconds Oct 16 17:26:54 klwurlitzer volumio[1201]: info: sendMpdCommand playlistinfo took 2 milliseconds Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::parseState Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::parseTrackInfo Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ControllerMpd::pushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::servicePushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":122,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"427251968","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/427251968","trackType":"qobuz"} Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: CURRENT POSITION 0 Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::syncState stateService play Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::syncState currentStatus stop Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ------------------------------ 33ms Oct 16 17:26:54 klwurlitzer volumio[1201]: info: sendMpdCommand playlistinfo took 7 milliseconds Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: ControllerMpd::parseTrackInfo Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ControllerMpd::pushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::servicePushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CorePlayQueue::getTrack 0 Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":122,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"427251968","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=qobuz://song/427251968","trackType":"qobuz"} Oct 16 17:26:54 klwurlitzer volumio[1201]: verbose: CURRENT POSITION 0 Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::syncState stateService play Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::syncState currentStatus play Oct 16 17:26:54 klwurlitzer volumio[1201]: info: Received an update from plugin. extracting info from payload Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreStateMachine::pushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioPushState Oct 16 17:26:54 klwurlitzer volumio[1201]: info: CoreCommandRouter::volumioGetState Oct 16 17:26:54 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:54.112+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 16 17:26:54 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:54.113+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" id=qobuz://song/427251968 title="We Will Rock You" Oct 16 17:26:54 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:54.114+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" state=STATUS_PLAYING positionMs=0 volume=100 Oct 16 17:26:54 klwurlitzer volumio5-onboarding[1365]: time=2026-10-16T17:26:54.114+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.20.88:39700,192.168.20.88:56174 @ 0x33de870" id=qobuz://song/427251968 title="We Will Rock You" Oct 16 17:26:54 klwurlitzer volumio[1201]: info: ------------------------------ 39ms Oct 16 17:26:54 klwurlitzer ntpd[831]: Soliciting pool server 85.215.166.214 Oct 16 17:26:54 klwurlitzer ntpd[831]: Soliciting pool server 130.162.251.109 Oct 16 17:26:54 klwurlitzer ntpd[831]: Soliciting pool server 78.47.56.71 Oct 16 17:26:54 klwurlitzer ntpd[831]: Soliciting pool server 134.60.111.110 Oct 16 17:26:54 klwurlitzer volumio[1201]: STREAMING PROXY: Resuming with range: bytes=38900- Oct 16 17:26:54 klwurlitzer volumio[1201]: STREAMING PROXY: Resume upstream status code: 206 Oct 16 17:26:55 klwurlitzer ntpd[831]: Soliciting pool server 95.89.38.215 Oct 16 17:26:55 klwurlitzer ntpd[831]: Soliciting pool server 85.220.190.246 Oct 16 17:26:55 klwurlitzer ntpd[831]: Soliciting pool server 78.46.53.2 Oct 16 17:26:55 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: qobuz , handleBrowseUri Oct 16 17:26:56 klwurlitzer ntpd[831]: Soliciting pool server 2a06:a880:5:d3cc::123 Oct 16 17:26:57 klwurlitzer volumio[1201]: info: handleBrowseUri took 1596 milliseconds Oct 16 17:26:57 klwurlitzer volumio[1201]: info: Preload queue cleared Oct 16 17:26:57 klwurlitzer volumio[1201]: info: Executing endpoint getSimilarArtists Oct 16 17:26:57 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Oct 16 17:26:57 klwurlitzer volumio[1201]: info: Executing endpoint metavolumio Oct 16 17:26:57 klwurlitzer volumio[1201]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 16 17:26:58 klwurlitzer volumio[1201]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 17:26:58 klwurlitzer volumio[1201]: Error: certificate is not yet valid Oct 16 17:26:58 klwurlitzer volumio[1201]: at TLSSocket.onConnectSecure (_tls_wrap.js:1497:34) Oct 16 17:26:58 klwurlitzer volumio[1201]: at TLSSocket.emit (events.js:315:20) Oct 16 17:26:58 klwurlitzer volumio[1201]: at TLSSocket._finishInit (_tls_wrap.js:932:8) Oct 16 17:26:58 klwurlitzer volumio[1201]: at TLSWrap.ssl.onhandshakedone (_tls_wrap.js:706:12) { Oct 16 17:26:58 klwurlitzer volumio[1201]: code: 'CERT_NOT_YET_VALID' Oct 16 17:26:58 klwurlitzer volumio[1201]: } Oct 16 17:26:58 klwurlitzer volumio[1201]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 17:26:58 klwurlitzer sudo[1862]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-10-16 17:25 Oct 16 17:26:58 klwurlitzer sudo[1862]: 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"