-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Tue 2026-02-17 19:17:35 UTC. -- Feb 17 19:16:00 vicky systemd[1]: Starting OpenBSD Secure Shell server... Feb 17 19:16:00 vicky systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Feb 17 19:16:00 vicky systemd[1]: Starting Permit User Sessions... Feb 17 19:16:00 vicky systemd[1]: Starting Network Time Service... Feb 17 19:16:00 vicky dhcpcd[489]: eth0: soliciting an IPv6 router Feb 17 19:16:00 vicky sh[423]: eth0: soliciting an IPv6 router Feb 17 19:16:00 vicky systemd[1]: Reached target Network is Online. Feb 17 19:16:00 vicky systemd[1]: Starting Samba NMB Daemon... Feb 17 19:16:00 vicky systemd[1]: Starting LSB: Brings up/down network automatically... Feb 17 19:16:00 vicky sh[423]: eth0: soliciting a DHCP lease Feb 17 19:16:00 vicky dhcpcd[489]: eth0: soliciting a DHCP lease Feb 17 19:16:00 vicky systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 17 19:16:00 vicky loadcpufreq[497]: Loading cpufreq kernel modules...done (none). Feb 17 19:16:00 vicky systemd[1]: Starting /etc/rc.local Compatibility... Feb 17 19:16:00 vicky systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Feb 17 19:16:00 vicky systemd[1]: Started Permit User Sessions. Feb 17 19:16:00 vicky systemd[1]: Started /etc/rc.local Compatibility. Feb 17 19:16:00 vicky systemd[1]: Starting Terminate Plymouth Boot Screen... Feb 17 19:16:00 vicky systemd[1]: Starting Hold until boot process finishes up... Feb 17 19:16:00 vicky systemd[1]: Starting LSB: set CPUFreq kernel parameters... Feb 17 19:16:00 vicky systemd[1]: Received SIGRTMIN+21 from PID 165 (plymouthd). Feb 17 19:16:00 vicky systemd[1]: plymouth-quit.service: Succeeded. Feb 17 19:16:00 vicky systemd[1]: Started Terminate Plymouth Boot Screen. Feb 17 19:16:00 vicky systemd[1]: plymouth-quit-wait.service: Succeeded. Feb 17 19:16:00 vicky systemd[1]: Started Hold until boot process finishes up. Feb 17 19:16:00 vicky systemd[1]: Received SIGRTMIN+21 from PID 165 (n/a). Feb 17 19:16:00 vicky sh[423]: eth0: offered 192.168.1.194 from 192.168.1.1 Feb 17 19:16:00 vicky dhcpcd[489]: eth0: offered 192.168.1.194 from 192.168.1.1 Feb 17 19:16:00 vicky systemd[1]: Started Getty on tty1. Feb 17 19:16:00 vicky systemd[1]: Started Serial Getty on ttyAMA0. Feb 17 19:16:00 vicky systemd[1]: Reached target Login Prompts. Feb 17 19:16:00 vicky ntpd[603]: ntpd 4.2.8p12@1.3728-o (1): Starting Feb 17 19:16:00 vicky ntpd[603]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Feb 17 19:16:00 vicky ntpd[625]: proto: precision = 1.093 usec (-20) Feb 17 19:16:00 vicky systemd[1]: Started Network Time Service. Feb 17 19:16:00 vicky ntpd[625]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Feb 17 19:16:00 vicky ntpd[625]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Feb 17 19:16:00 vicky ntpd[625]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 417 days ago Feb 17 19:16:00 vicky ntpd[625]: Listen and drop on 0 v6wildcard [::]:123 Feb 17 19:16:00 vicky ntpd[625]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Feb 17 19:16:00 vicky ntpd[625]: Listen normally on 2 lo 127.0.0.1:123 Feb 17 19:16:00 vicky ntpd[625]: Listening on routing socket on fd #19 for interface updates Feb 17 19:16:00 vicky ntpd[625]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 17 19:16:00 vicky ntpd[625]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 17 19:16:00 vicky ifplugd(eth0)[640]: ifplugd 0.28 initializing. Feb 17 19:16:00 vicky ifplugd(eth0)[640]: Using interface eth0/B8:27:EB:06:A6:D6 with driver (version: 6.6.62-v7+) Feb 17 19:16:00 vicky ifplugd(eth0)[640]: Using detection mode: SIOCETHTOOL Feb 17 19:16:00 vicky ifplugd(eth0)[640]: Initialization complete, link beat detected. Feb 17 19:16:00 vicky ifplugd(eth0)[640]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Feb 17 19:16:00 vicky sh[423]: eth0: probing address 192.168.1.194/24 Feb 17 19:16:00 vicky dhcpcd[489]: eth0: probing address 192.168.1.194/24 Feb 17 19:16:00 vicky sshd[641]: Server listening on 0.0.0.0 port 22. Feb 17 19:16:00 vicky systemd[1]: Started OpenBSD Secure Shell server. Feb 17 19:16:00 vicky sshd[641]: Server listening on :: port 22. Feb 17 19:16:00 vicky cpufrequtils[616]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Feb 17 19:16:00 vicky systemd[1]: Started LSB: set CPUFreq kernel parameters. Feb 17 19:16:00 vicky ifplugd(eth0)[640]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Feb 17 19:16:01 vicky ntpd[625]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Feb 17 19:16:01 vicky nmbd[613]: [2026/02/17 19:16:01.896645, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Feb 17 19:16:01 vicky nmbd[613]: started asyncdns process 659 Feb 17 19:16:01 vicky nmbd[613]: [2026/02/17 19:16:01.901139, 0] ../lib/util/become_daemon.c:149(daemon_status) Feb 17 19:16:01 vicky nmbd[613]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Feb 17 19:16:01 vicky nmbd[613]: [2026/02/17 19:16:01.901732, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Feb 17 19:16:01 vicky nmbd[613]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Feb 17 19:16:02 vicky ntpd[625]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Feb 17 19:16:02 vicky wireless.js[494]: WIRELESS: No wireless interface, exiting Feb 17 19:16:02 vicky iw[664]: command failed: No such device (-19) Feb 17 19:16:02 vicky iwconfig[667]: Error for wireless request "Set Power Management" (8B2C) : Feb 17 19:16:02 vicky iwconfig[667]: SET failed on device wlan0 ; No such device. Feb 17 19:16:02 vicky systemd[1]: wireless.service: Succeeded. Feb 17 19:16:02 vicky systemd[1]: Started Wireless Services. Feb 17 19:16:02 vicky systemd[1]: Started Volumio Backend Module. Feb 17 19:16:02 vicky systemd[1]: Started Volumio Cpu Tweaker. Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: Setting RT Priority for mpd Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: pid 35's current scheduling policy: SCHED_OTHER Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: pid 35's current scheduling priority: 0 Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: Setting MPD Affinity Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: pid 3's current affinity mask: f Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Feb 17 19:16:03 vicky volumio-cpu-tweak[671]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Feb 17 19:16:03 vicky systemd[1]: volumio_cpu_tweak.service: Succeeded. Feb 17 19:16:03 vicky ntpd[625]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Feb 17 19:16:04 vicky ntpd[625]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Feb 17 19:16:04 vicky volumio-remote-updater[455]: [2026-02-17 19:16:04] [info] asio async_connect error: system:111 (Connection refused) Feb 17 19:16:04 vicky volumio-remote-updater[455]: [2026-02-17 19:16:04] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 17 19:16:04 vicky volumio-remote-updater[455]: [2026-02-17 19:16:04] [error] handle_connect error: Underlying Transport Error Feb 17 19:16:04 vicky volumio-time-update[471]: volumio-time-update-util: Fetching time from Volumio... Feb 17 19:16:04 vicky volumio-time-update[471]: volumio-time-update-util: Date not found in response Feb 17 19:16:04 vicky volumio-time-update[471]: volumio-time-update-util: Retrying in 5 seconds... Feb 17 19:16:05 vicky sh[423]: eth0: leased 192.168.1.194 for 86400 seconds Feb 17 19:16:05 vicky sh[423]: eth0: adding route to 192.168.1.0/24 Feb 17 19:16:05 vicky sh[423]: eth0: adding default route via 192.168.1.1 Feb 17 19:16:05 vicky dhcpcd[489]: eth0: leased 192.168.1.194 for 86400 seconds Feb 17 19:16:05 vicky avahi-daemon[475]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.194. Feb 17 19:16:05 vicky dhcpcd[489]: eth0: adding route to 192.168.1.0/24 Feb 17 19:16:05 vicky avahi-daemon[475]: New relevant interface eth0.IPv4 for mDNS. Feb 17 19:16:05 vicky dhcpcd[489]: eth0: adding default route via 192.168.1.1 Feb 17 19:16:05 vicky avahi-daemon[475]: Registering new address record for 192.168.1.194 on eth0.IPv4. Feb 17 19:16:05 vicky sh[423]: forked to background, child pid 713 Feb 17 19:16:05 vicky dhcpcd[489]: forked to background, child pid 713 Feb 17 19:16:06 vicky ifplugd(eth0)[640]: client: ifup: interface eth0 already configured Feb 17 19:16:06 vicky sh[423]: eth0=eth0 Feb 17 19:16:06 vicky ifplugd(eth0)[640]: Program executed successfully. Feb 17 19:16:06 vicky ifplugd[606]: Network Interface Plugging Daemon...start eth0...done. Feb 17 19:16:06 vicky systemd[1]: Started LSB: Brings up/down network automatically. Feb 17 19:16:06 vicky nmbd[613]: [2026/02/17 19:16:06.945854, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 17 19:16:06 vicky nmbd[613]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Feb 17 19:16:06 vicky systemd[1]: Started Samba NMB Daemon. Feb 17 19:16:07 vicky systemd[1]: Starting Samba Winbind Daemon... Feb 17 19:16:07 vicky ntpd[625]: Listen normally on 3 eth0 192.168.1.194:123 Feb 17 19:16:07 vicky ntpd[625]: new interface(s) found: waking up resolver Feb 17 19:16:07 vicky winbindd[739]: [2026/02/17 19:16:07.631193, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Feb 17 19:16:07 vicky winbindd[739]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Feb 17 19:16:07 vicky winbindd[739]: [2026/02/17 19:16:07.719443, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 17 19:16:07 vicky winbindd[739]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Feb 17 19:16:07 vicky systemd[1]: Started Samba Winbind Daemon. Feb 17 19:16:07 vicky systemd[1]: Starting Samba SMB Daemon... Feb 17 19:16:08 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:16:08 vicky volumio[670]: info: ----- Volumio3 ---- Feb 17 19:16:08 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:16:08 vicky volumio[670]: info: ----- System startup ---- Feb 17 19:16:08 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:16:08 vicky smbd[752]: [2026/02/17 19:16:08.820752, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 17 19:16:08 vicky smbd[752]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Feb 17 19:16:08 vicky systemd[1]: Started Samba SMB Daemon. Feb 17 19:16:09 vicky volumio-time-update[471]: volumio-time-update-util: Fetching time from Volumio... Feb 17 19:16:10 vicky volumio-time-update[471]: volumio-time-update-util: Setting system time to: 2026-02-17 19:17:08 Feb 17 19:16:10 vicky sudo[765]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2026-02-17 19:17:08 Feb 17 19:16:10 vicky sudo[765]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:16:10 vicky dbus-daemon[480]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.6' (uid=0 pid=766 comm="timedatectl set-time 2026-02-17 19:17:08 ") Feb 17 19:16:10 vicky systemd[1]: Starting Time & Date Service... Feb 17 19:16:10 vicky volumio[670]: info: MYVOLUMIO Environment detected Feb 17 19:16:10 vicky volumio[670]: info: Found new core plugin system_controller/volumio5onboarding. Adding it Feb 17 19:16:10 vicky dbus-daemon[480]: [system] Successfully activated service 'org.freedesktop.timedate1' Feb 17 19:16:10 vicky systemd[1]: Started Time & Date Service. Feb 17 19:17:08 vicky systemd-timedated[767]: Changed local time to Tue Feb 17 19:17:08 2026 Feb 17 19:17:08 vicky sudo[765]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:08 vicky volumio-time-update[471]: volumio-time-update-util: System time updated successfully. Feb 17 19:17:08 vicky systemd[1]: Started Volumio Time Update Utility. Feb 17 19:17:08 vicky systemd[1]: Reached target Multi-User System. Feb 17 19:17:08 vicky systemd[1]: Reached target Graphical Interface. Feb 17 19:17:08 vicky systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 17 19:17:08 vicky volumio[670]: info: Plugin folders cleanup Feb 17 19:17:08 vicky volumio[670]: info: Scanning into folder /volumio/app/plugins/ Feb 17 19:17:08 vicky volumio[670]: info: Scanning category audio_interface Feb 17 19:17:08 vicky volumio[670]: info: Scanning category miscellanea Feb 17 19:17:08 vicky volumio[670]: info: Scanning category music_service Feb 17 19:17:08 vicky volumio[670]: info: Scanning category plugins.json Feb 17 19:17:08 vicky volumio[670]: info: Scanning category system_controller Feb 17 19:17:08 vicky volumio[670]: info: Scanning category user_interface Feb 17 19:17:08 vicky volumio[670]: info: Scanning into folder /data/plugins/ Feb 17 19:17:08 vicky volumio[670]: info: Scanning category audio_interface Feb 17 19:17:08 vicky volumio[670]: info: Scanning category music_service Feb 17 19:17:08 vicky volumio[670]: info: Plugin folders cleanup completed Feb 17 19:17:08 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:17:08 vicky volumio[670]: info: ----- Core plugins startup ---- Feb 17 19:17:08 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:17:08 vicky volumio[670]: info: Loading plugins from folder /volumio/app/plugins/ Feb 17 19:17:08 vicky volumio[670]: info: Adding plugin upnp to MyMusic Plugins Feb 17 19:17:08 vicky volumio[670]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 17 19:17:08 vicky volumio[670]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 17 19:17:08 vicky systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 17 19:17:08 vicky systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 17 19:17:08 vicky volumio[670]: info: Loading plugins from folder /data/plugins/ Feb 17 19:17:08 vicky systemd[1]: Startup finished in 15.278s (kernel) + 20.207s (userspace) = 35.486s. Feb 17 19:17:08 vicky volumio[670]: info: Loading plugin "system"... Feb 17 19:17:08 vicky volumio[670]: info: Loading plugin "appearance"... Feb 17 19:17:09 vicky volumio-remote-updater[455]: [2026-02-17 19:17:09] [connect] Successful connection Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "network"... Feb 17 19:17:11 vicky volumio[670]: info: Refreshing Cached IP Addresses Feb 17 19:17:11 vicky sudo[775]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 19:17:11 vicky sudo[775]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:11 vicky sudo[777]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 19:17:11 vicky sudo[777]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:11 vicky sudo[775]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "services"... Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "volumio5onboarding"... Feb 17 19:17:11 vicky sudo[777]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:11 vicky sudo[786]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 17 19:17:11 vicky sudo[786]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:11 vicky sudo[786]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "alsa_controller"... Feb 17 19:17:11 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "wizard"... Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "networkfs"... Feb 17 19:17:11 vicky volumio[670]: info: Starting Udev Watcher for removable devices Feb 17 19:17:11 vicky sudo[805]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=freddie,password=l4rvae42,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.2/robox\\music\\high_quality /mnt/NAS/robox Feb 17 19:17:11 vicky sudo[805]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:11 vicky volumio[670]: info: Ignoring mount for partition: boot Feb 17 19:17:11 vicky volumio[670]: info: Ignoring mount for partition: volumio Feb 17 19:17:11 vicky volumio[670]: info: Ignoring mount for partition: volumio_data Feb 17 19:17:11 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "volumio_command_line_client"... Feb 17 19:17:11 vicky volumio[670]: info: Plugin upnp is not enabled Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "my_music"... Feb 17 19:17:11 vicky volumio[670]: info: Loading plugin "mpd"... Feb 17 19:17:12 vicky kernel: Key type cifs.spnego registered Feb 17 19:17:12 vicky kernel: Key type cifs.idmap registered Feb 17 19:17:12 vicky kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Feb 17 19:17:12 vicky kernel: CIFS: Attempting to mount //192.168.1.2/robox/music/high_quality Feb 17 19:17:12 vicky kernel: cryptd: max_cpu_qlen set to 1000 Feb 17 19:17:12 vicky sudo[805]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:13 vicky volumio[670]: info: Loading plugin "upnp_browser"... Feb 17 19:17:14 vicky volumio[670]: info: Starting UPNP Browser Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "alarm-clock"... Feb 17 19:17:14 vicky volumio[670]: info: Plugin airplay_emulation is not enabled Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "last_100"... Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "webradio"... Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "i2s_dacs"... Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "volumiodiscovery"... Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** For more information see Feb 17 19:17:14 vicky node[670]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 19:17:14 vicky volumio[670]: *** WARNING *** For more information see Feb 17 19:17:14 vicky node[670]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 19:17:14 vicky node[670]: *** WARNING *** For more information see Feb 17 19:17:14 vicky node[670]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 17 19:17:14 vicky node[670]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 17 19:17:14 vicky node[670]: *** WARNING *** For more information see Feb 17 19:17:14 vicky volumio[670]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 17 19:17:14 vicky volumio[670]: info: Discovery: Started advertising with name: Vicky Feb 17 19:17:14 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 17 19:17:14 vicky volumio[670]: info: Loading plugin "mixcloud"... Feb 17 19:17:16 vicky volumio[670]: info: Loading plugin "spop"... Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "outputs"... Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "albumart"... Feb 17 19:17:19 vicky volumio[670]: info: Plugin example_plugin is not enabled Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "inputs"... Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "updater_comm"... Feb 17 19:17:19 vicky volumio[670]: info: Plugin mpdemulation is not enabled Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "rest_api"... Feb 17 19:17:19 vicky volumio[670]: info: Loading plugin "websocket"... Feb 17 19:17:20 vicky volumio[670]: info: Starting Socket.io Server version 2.3.0 Feb 17 19:17:20 vicky volumio[670]: info: Loading plugin "fusiondsp"... Feb 17 19:17:20 vicky volumio[670]: Forking 3 albumart workers Feb 17 19:17:20 vicky volumio[670]: info: Applying required configuration parameters for plugin fusiondsp Feb 17 19:17:21 vicky volumio[670]: info: Loading i18n strings for locale en Feb 17 19:17:21 vicky volumio[670]: Updating browse sources language Feb 17 19:17:21 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::initPlayerControls Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 19:17:22 vicky volumio[670]: Express server listening on port 3000 Feb 17 19:17:22 vicky volumio[670]: [Metrics] WebUI: 18s 915.94ms Feb 17 19:17:22 vicky volumio[670]: Starting albumart workers Feb 17 19:17:22 vicky volumio[670]: info: CoreStateMachine::resetVolumioState Feb 17 19:17:22 vicky volumio[670]: info: CoreStateMachine::getcurrentVolume Feb 17 19:17:22 vicky volumio[670]: info: CoreCommandRouter::volumioRetrievevolume Feb 17 19:17:22 vicky volumio[670]: Starting albumart workers Feb 17 19:17:22 vicky volumio[670]: info: Volumio Network Manager: Network status updated: 1 Feb 17 19:17:22 vicky volumio[670]: Starting albumart workers Feb 17 19:17:22 vicky volumio[670]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Feb 17 19:17:22 vicky volumio[670]: wlan0 Interface doesn't support scanning. Feb 17 19:17:22 vicky volumio[670]: info: Cannot use regular scanning, forcing with ap-force Feb 17 19:17:22 vicky sudo[896]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Feb 17 19:17:22 vicky sudo[896]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:22 vicky sudo[896]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:22 vicky volumio[670]: command failed: No such device (-19) Feb 17 19:17:22 vicky volumio[670]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Feb 17 19:17:22 vicky volumio[670]: command failed: No such device (-19) Feb 17 19:17:22 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194 from 192.168.1.237 UA: Mozilla/5.0 (Linux; Android 16; SM-F731B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.45 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Feb 17 19:17:23 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194:3000 from 192.168.1.237 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 2 Feb 17 19:17:23 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194:3000 from 192.168.1.237 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 3 Feb 17 19:17:23 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194:3000 from 192.168.1.237 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Feb 17 19:17:23 vicky volumio[670]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:23 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:23 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 19:17:23 vicky volumio[670]: info: Reloading queue from file Feb 17 19:17:23 vicky volumio[670]: info: VolumeController:: Volume=undefined Mute =false Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::pushState Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioPushState Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::updateTrackBlock Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrackBlock Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioRetrievevolume Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::setRepeat true single undefined Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::pushState Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioPushState Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::setRandom true Feb 17 19:17:23 vicky volumio[670]: info: CoreStateMachine::pushState Feb 17 19:17:23 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 19:17:23 vicky volumio[670]: info: CoreCommandRouter::volumioPushState Feb 17 19:17:23 vicky volumio[670]: info: Setting Device type: Raspberry PI Feb 17 19:17:23 vicky volumio[670]: info: Completed loading Core Plugins Feb 17 19:17:23 vicky volumio[670]: info: Preparing to generate the ALSA configuration file Feb 17 19:17:23 vicky volumio[670]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Feb 17 19:17:23 vicky volumio[670]: info: Reading ALSA contributions from plugins. Feb 17 19:17:23 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194:3000 from 192.168.1.237 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Feb 17 19:17:23 vicky volumio[670]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 17 19:17:24 vicky volumio[670]: info: Discovery: adding 1db92c68-9f09-4ce1-9d1c-d69b89124ea7 Feb 17 19:17:24 vicky volumio[670]: info: Discovery: Found device Vicky Feb 17 19:17:24 vicky systemd[1]: systemd-fsckd.service: Succeeded. Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:24 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:24 vicky volumio[670]: info: VolumeController:: Volume=undefined Mute =false Feb 17 19:17:24 vicky volumio[670]: info: CoreStateMachine::pushState Feb 17 19:17:24 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioPushState Feb 17 19:17:24 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194:3000 from 192.168.1.237 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:24 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:24 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:24 vicky volumio[670]: info: Asound.conf file unchanged, so no further update is needed Feb 17 19:17:24 vicky volumio[670]: info: Output device has changed, restarting MPD Feb 17 19:17:24 vicky volumio[670]: info: ___________ START PLUGINS ___________ Feb 17 19:17:24 vicky sudo[933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 19:17:24 vicky sudo[933]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky sudo[933]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:24 vicky sudo[935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 19:17:24 vicky volumio[670]: info: ControllerMpd::onStart: Initializing MPD Feb 17 19:17:24 vicky volumio[670]: info: Creating MPD Configuration file Feb 17 19:17:24 vicky sudo[935]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky volumio-remote-updater[455]: [2026-02-17 19:17:24] [connect] Successful connection Feb 17 19:17:24 vicky sudo[938]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Feb 17 19:17:24 vicky sudo[938]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 19:17:24 vicky volumio[670]: info: [1771355844387] CoreMusicLibrary::Adding element Media Servers Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:24 vicky sudo[941]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 19:17:24 vicky sudo[941]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky sudo[941]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:24 vicky sudo[943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 19:17:24 vicky sudo[943]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky volumio[670]: info: UPNP Browser: Client initialized successfully Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 19:17:24 vicky volumio[670]: info: [1771355844473] CoreMusicLibrary::Adding element Last_100 Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 19:17:24 vicky volumio[670]: info: [1771355844479] CoreMusicLibrary::Adding element Webradio Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 19:17:24 vicky volumio[670]: info: Initializing BBC Radios Feb 17 19:17:24 vicky systemd[1]: Listening on mpd.socket. Feb 17 19:17:24 vicky systemd[1]: Starting Music Player Daemon... Feb 17 19:17:24 vicky systemd[1]: Started Volumio5 Onboarding Server. Feb 17 19:17:24 vicky systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Feb 17 19:17:24 vicky systemd[1]: mpd.service: Succeeded. Feb 17 19:17:24 vicky sudo[938]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:24 vicky systemd[1]: Stopped Music Player Daemon. Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 19:17:24 vicky systemd[1]: Starting Music Player Daemon... Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 17 19:17:24 vicky volumio[670]: info: [1771355844665] CoreMusicLibrary::Adding element Mixcloud Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:24 vicky volumio[670]: Cannot find translation for source Mixcloud Feb 17 19:17:24 vicky volumio[670]: info: Creating Spotify config file Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:24 vicky sudo[960]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 19:17:24 vicky sudo[960]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:24 vicky sudo[960]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 17 19:17:24 vicky sudo[960]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:24 vicky volumio[670]: info: Loading i18n strings for locale en Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Feb 17 19:17:24 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:24 vicky volumio[670]: info: FusionDsp - mixtype--------------------- undefined Feb 17 19:17:24 vicky volumio[670]: info: Volumio Calling Home Feb 17 19:17:25 vicky volumio[670]: info: Preparing to generate the ALSA configuration file Feb 17 19:17:25 vicky volumio[670]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Feb 17 19:17:25 vicky volumio[670]: info: Reading ALSA contributions from plugins. Feb 17 19:17:25 vicky volumio[670]: info: MPD Permissions set Feb 17 19:17:25 vicky volumio[670]: info: MPD Permissions set Feb 17 19:17:25 vicky volumio-remote-updater[455]: [2026-02-17 19:17:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1771355844 101 Feb 17 19:17:25 vicky volumio[670]: 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: 6 Feb 17 19:17:25 vicky volumio[670]: info: Volumio called home Feb 17 19:17:25 vicky volumio[670]: info: Spotify config file written Feb 17 19:17:25 vicky sudo[972]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 17 19:17:25 vicky sudo[972]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:25 vicky volumio[670]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 17 19:17:25 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:25.640Z level=INFO msg="running volumio5-device-gateway" version=30d1950e+CHANGES buildDate=2026-01-29T13:10:08Z Feb 17 19:17:25 vicky volumio[670]: info: No need to fix Spotify hosts Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky systemd[1]: Started go-librespot Daemon. Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky go-librespot[974]: go-librespot daemon starting... Feb 17 19:17:25 vicky sudo[972]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 19:17:25 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 17 19:17:26 vicky volumio[670]: 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: 8 Feb 17 19:17:26 vicky volumio[670]: 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: 8 Feb 17 19:17:26 vicky dbus-daemon[480]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.12' (uid=0 pid=956 comm="/usr/bin/volumio5-onboarding ") Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:26 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:26 vicky systemd[1]: Starting Bluetooth service... Feb 17 19:17:26 vicky volumio[670]: info: Asound.conf file unchanged, so no further update is needed Feb 17 19:17:26 vicky volumio[670]: info: Output device has changed, restarting MPD Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky sudo[997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 19:17:26 vicky sudo[995]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 19:17:26 vicky sudo[997]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:26 vicky sudo[995]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:26 vicky sudo[995]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:26 vicky systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 17 19:17:26 vicky systemd[1]: mpd.service: Succeeded. Feb 17 19:17:26 vicky systemd[1]: Stopped Music Player Daemon. Feb 17 19:17:26 vicky volumio[670]: info: MPD Permissions set Feb 17 19:17:26 vicky systemd[1]: Starting Music Player Daemon... Feb 17 19:17:26 vicky go-librespot[974]: time="2026-02-17T19:17:26Z" level=info msg="running go-librespot 0.4.0" Feb 17 19:17:26 vicky go-librespot[974]: time="2026-02-17T19:17:26Z" level=debug msg="app state loaded" Feb 17 19:17:26 vicky go-librespot[974]: time="2026-02-17T19:17:26Z" level=debug msg="stored credentials not found" Feb 17 19:17:26 vicky go-librespot[974]: time="2026-02-17T19:17:26Z" level=info msg="api server listening on 127.0.0.1:9879" Feb 17 19:17:26 vicky kernel: Bluetooth: Core ver 2.22 Feb 17 19:17:26 vicky kernel: NET: Registered PF_BLUETOOTH protocol family Feb 17 19:17:26 vicky kernel: Bluetooth: HCI device and connection manager initialized Feb 17 19:17:26 vicky kernel: Bluetooth: HCI socket layer initialized Feb 17 19:17:26 vicky kernel: Bluetooth: L2CAP socket layer initialized Feb 17 19:17:26 vicky kernel: Bluetooth: SCO socket layer initialized Feb 17 19:17:26 vicky bluetoothd[993]: Bluetooth daemon 5.83 Feb 17 19:17:26 vicky bluetoothd[993]: src/main.c:check_options() Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Feb 17 19:17:26 vicky dbus-daemon[480]: [system] Successfully activated service 'org.bluez' Feb 17 19:17:26 vicky systemd[1]: Started Bluetooth service. Feb 17 19:17:26 vicky bluetoothd[993]: Starting SDP server Feb 17 19:17:26 vicky bluetoothd[993]: Excluding (cli) hostname Feb 17 19:17:26 vicky bluetoothd[993]: Excluding (cli) scanparam Feb 17 19:17:26 vicky bluetoothd[993]: Excluding (cli) battery Feb 17 19:17:26 vicky kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Feb 17 19:17:26 vicky kernel: Bluetooth: BNEP filters: protocol multicast Feb 17 19:17:26 vicky kernel: Bluetooth: BNEP socket layer initialized Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.927Z level=WARN msg="failed to enable Bluetooth adapter" adapter=hci0 error="bluetooth: adapter /org/bluez/hci0 does not exist" Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.933Z level=WARN msg="failed to enable Bluetooth adapter" adapter=hci1 error="bluetooth: adapter /org/bluez/hci1 does not exist" Feb 17 19:17:26 vicky bluetoothd[993]: Bluetooth management interface 1.22 initialized Feb 17 19:17:26 vicky sudo[1004]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.943Z level=WARN msg="failed to enable Bluetooth adapter" adapter=hci2 error="bluetooth: adapter /org/bluez/hci2 does not exist" Feb 17 19:17:26 vicky sudo[1004]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.950Z level=WARN msg="failed to enable Bluetooth adapter" adapter=hci3 error="bluetooth: adapter /org/bluez/hci3 does not exist" Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.959Z level=WARN msg="failed to enable Bluetooth adapter" adapter=hci4 error="bluetooth: adapter /org/bluez/hci4 does not exist" Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.959Z level=WARN msg="no Bluetooth adapter found, BLE discovery disabled" Feb 17 19:17:26 vicky sudo[1004]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 17 19:17:26 vicky sudo[1004]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:26 vicky volumio[670]: info: Received Get System Info Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:26 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:26 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:26 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:26 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:26.987Z level=INFO msg="system info for 5fa4ce8a57cccfcfd0d0b38ee24179f4" deviceName=Vicky deviceVariant=volumio deviceModel= softwareVersion=3.908 Feb 17 19:17:27 vicky volumio[670]: info: camilladsp service started and running in background, instance 1 Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 176400 192000 <-AAAAAAAAAAAAA Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp loaded Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:27 vicky sudo[1025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Feb 17 19:17:27 vicky sudo[1025]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp - Reporting Fusion DSP Enabled Feb 17 19:17:27 vicky volumio[670]: info: Adding Signal Path Element [object Object] Feb 17 19:17:27 vicky volumio[670]: info: Adding fusiondspeq DSP Signal Path Element Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp - ---- installed callbackRead Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 17 19:17:27 vicky systemd[1]: Started FusionDsp Daemon. Feb 17 19:17:27 vicky volumio[670]: info: Received Get System Info Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:27 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:27 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:27 vicky sudo[1025]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:27 vicky kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Feb 17 19:17:27 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:27.585Z level=INFO msg="enabling local network discovery" Feb 17 19:17:27 vicky volumio[670]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Feb 17 19:17:27 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:27.662Z level=INFO msg="bootstrapping state" hasInternet=true Feb 17 19:17:27 vicky volumio[670]: info: FusionDsp - {"Reload":{"result":"Ok"}} Feb 17 19:17:27 vicky volumio[670]: info: Received Get System Info Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:27 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:27 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:27 vicky go-librespot[974]: time="2026-02-17T19:17:27Z" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 17 19:17:27 vicky go-librespot[974]: time="2026-02-17T19:17:27Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 17 19:17:27 vicky go-librespot[974]: time="2026-02-17T19:17:27Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 17 19:17:27 vicky volumio-remote-updater[455]: No test mode Feb 17 19:17:27 vicky volumio-remote-updater[455]: No alpha test mode Feb 17 19:17:27 vicky go-librespot[974]: time="2026-02-17T19:17:27Z" level=info msg="zeroconf server listening on port 46547" Feb 17 19:17:27 vicky volumio[670]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 19:17:27 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:27.971Z level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Feb 17 19:17:27 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:27.976Z level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Feb 17 19:17:27 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:27.977Z level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Feb 17 19:17:27 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 19:17:28 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 19:17:29 vicky volumio[670]: info: go-librespot daemon successfully initialized Feb 17 19:17:29 vicky volumio5-onboarding[956]: time=2026-02-17T19:17:29.104Z level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.237:36306 Feb 17 19:17:29 vicky sudo[1038]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 19:17:29 vicky sudo[1038]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:29 vicky sudo[1038]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:29 vicky sudo[1040]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 19:17:29 vicky sudo[1040]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:29 vicky sudo[1040]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:30 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194 from 192.168.1.237 UA: Mozilla/5.0 (Linux; Android 16; SM-F731B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.45 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Feb 17 19:17:30 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 17 19:17:31 vicky sudo[1046]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 17 19:17:31 vicky sudo[1046]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:31 vicky sudo[1048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 17 19:17:31 vicky sudo[1046]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:31 vicky sudo[1048]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="obtained new client token: AABW+pZIdyJVzxvhGIA9OV6Qqlo2vkO4WNlEJ8ZDQTxXkSZo+kdS6iZgwE8HzFrERBMYTucLFHZAO7/O/28cSlWjK7TSHKA6TWbEyYpuMyiMdMYxfghI2ckL0MmxlCL2g8VGajQvbHtGLq9usXz0foEyuSqedhtBe4dot4mC3Jgs0PeLu9w619+x4spHJ6zBrfCtr6CGD3CG5/1D/DGMpHKLxZXgPzD1JI7bKZAeXVnaJJeUV5Uo0bwn" Feb 17 19:17:31 vicky sudo[1048]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 17 19:17:31 vicky volumio[670]: verbose: New Socket.io Connection to 192.168.1.194 from 192.168.1.237 UA: Mozilla/5.0 (Linux; Android 16; SM-F731B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/145.0.7632.45 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="completed keyexchange" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="completed challenge" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=info msg="authenticated AP" username="ur**ue" Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=info msg="authenticated Login5" username="ur**ue" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=info msg="accepted zeroconf from Mhyrrz" username="ur**ue" Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::volumioGetVisibleSources Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:31 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 17 19:17:31 vicky volumio[670]: info: Received Get System Info Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:31 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:31 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:31 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="dealer connection opened" Feb 17 19:17:31 vicky volumio[670]: info: Listing playlists Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=trace msg="starting accesspoint recv loop" Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 17 19:17:31 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=trace msg="starting dealer recv loop" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=trace msg="received accesspoint ping" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 17 19:17:31 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:31Z" level=debug msg="received connection id: YTgwZWQ5M2ItYzI1...ODg2QkEwMTYxMQ==" Feb 17 19:17:32 vicky volumio[670]: info: Initializing connection to go-librespot Websocket Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=trace msg="received accesspoint pong ack" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="new websocket client" Feb 17 19:17:32 vicky volumio[670]: info: Connection to go-librespot Websocket established Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="put connect state because NEW_DEVICE" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="handling transfer player command from de3c1ca0802e799f7e8a5e2a358f8e6480381d67" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="shuffled context with seed 8778080484626136527 (len: 50, keep: 36)" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="loading track (paused: false, position: 232530ms)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=trace msg="emitting websocket event: will_play" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="selected format OGG_VORBIS_320 (3f59d2dca8b4777ded596180e517691ccd521155)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="requested aes key for file 3f59d2dca8b4777ded596180e517691ccd521155, gid: 4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=trace msg="found 2 cdn urls" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:32 vicky volumio[670]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 19:17:32 vicky volumio[670]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E8DSLzIEI7K30","uri":"spotify:track:4mT7rUXqBdj7fgOY1D4prp","play_origin":"playlist"}} Feb 17 19:17:32 vicky volumio[670]: info: FusionDsp - Feb 17 19:17:32 vicky go-librespot[974]: time="2026-02-17T19:17:32Z" level=debug msg="fetched first chunk of 16, total size is 8258956 bytes" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:32 vicky mpd[1012]: Feb 17 19:17 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 17 19:17:33 vicky systemd[1]: Started Music Player Daemon. Feb 17 19:17:33 vicky sudo[997]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:33 vicky sudo[943]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:33 vicky sudo[935]: pam_unix(sudo:session): session closed for user root Feb 17 19:17:33 vicky volumio[670]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="fetched chunk 15/15, size: 394636" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="seek to 208333ms (diff: 1129ms, samples: 9187485, bytes: 8231750)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="created new output device" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky volumio[670]: info: Completed starting Core Plugins Feb 17 19:17:33 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:17:33 vicky volumio[670]: info: ----- MyVolumio plugins startup ---- Feb 17 19:17:33 vicky volumio[670]: info: ------------------------------------------- Feb 17 19:17:33 vicky volumio[670]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 17 19:17:33 vicky volumio[670]: info: VolumeController::SetAlsaVolume0 Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=info msg="loaded track \"Katie Queen of Tennessee\" (paused: false, position: 232530ms, duration: 208333ms, prefetched: false)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 17 19:17:33 vicky volumio[670]: info: Received Get System Info Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 17 19:17:33 vicky volumio[670]: info: Discovery: Getting this device information Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:33 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 17 19:17:33 vicky volumio[670]: info: CoreStateMachine::pushState Feb 17 19:17:33 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 19:17:33 vicky volumio[670]: info: CoreCommandRouter::volumioPushState Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="prefetching next track" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="emitting websocket event: metadata" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="emitting websocket event: active" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="sending successful reply for dealer request" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="selected format OGG_VORBIS_320 (966e9d350cf41d89d87ca4330f2b1369d49cb4e1)" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="requested aes key for file 966e9d350cf41d89d87ca4330f2b1369d49cb4e1, gid: 0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="emitting websocket event: playing" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="handling play player command from de3c1ca0802e799f7e8a5e2a358f8e6480381d67" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="shuffled context with seed 7491735022570931053 (len: 50, keep: 25)" uri="spotify:playlist:37i9dQZF1E8DSLzIEI7K30" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="found 2 cdn urls" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=trace msg="emitting websocket event: will_play" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="selected format OGG_VORBIS_320 (3f59d2dca8b4777ded596180e517691ccd521155)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky go-librespot[974]: time="2026-02-17T19:17:33Z" level=debug msg="requested aes key for file 3f59d2dca8b4777ded596180e517691ccd521155, gid: 4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:33 vicky volumio[670]: error: MPD error: The expression evaluated to a falsy value: Feb 17 19:17:33 vicky volumio[670]: assert.ok(self.idling) Feb 17 19:17:33 vicky volumio[670]: error: The expression evaluated to a falsy value: Feb 17 19:17:33 vicky volumio[670]: assert.ok(self.idling) Feb 17 19:17:33 vicky volumio[670]: error: MPD error: The expression evaluated to a falsy value: Feb 17 19:17:33 vicky volumio[670]: assert.ok(self.idling) Feb 17 19:17:33 vicky volumio[670]: error: The expression evaluated to a falsy value: Feb 17 19:17:33 vicky volumio[670]: assert.ok(self.idling) Feb 17 19:17:33 vicky volumio[670]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Feb 17 19:17:33 vicky volumio[670]: info: FusionDsp - ---- read samplerate from file: 44100 Feb 17 19:17:33 vicky volumio[670]: info: camilladsp stopping service pid 1019... Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=trace msg="found 2 cdn urls" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:34 vicky volumio[670]: info: camilladsp service terminated, instance 1 Feb 17 19:17:34 vicky volumio[670]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 17 19:17:34 vicky volumio[670]: info: camilladsp service started and running in background, instance 1 Feb 17 19:17:34 vicky volumio[670]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4mT7rUXqBdj7fgOY1D4prp","name":"Katie Queen of Tennessee","artist_names":["The Apache Relay"],"album_name":"The Apache Relay","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0285c448cb4da2ab99ea87ffa4","position":232530,"duration":208333,"release_date":"year:2015 month:5 day:15","track_number":1,"disc_number":1}} Feb 17 19:17:34 vicky volumio[670]: SPOTIFY: received: {"type":"active","data":null} Feb 17 19:17:34 vicky volumio[670]: info: Aligning Spotify Volume to Volumio Volume Feb 17 19:17:34 vicky volumio[670]: info: CoreCommandRouter::volumioGetState Feb 17 19:17:34 vicky volumio[670]: info: CorePlayQueue::getTrack 0 Feb 17 19:17:34 vicky volumio[670]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E8DSLzIEI7K30","uri":"spotify:track:4mT7rUXqBdj7fgOY1D4prp","resume":false,"play_origin":"playlist"}} Feb 17 19:17:34 vicky volumio[670]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 19:17:34 vicky volumio[670]: TypeError: Cannot read property 'service' of undefined Feb 17 19:17:34 vicky volumio[670]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Feb 17 19:17:34 vicky volumio[670]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Feb 17 19:17:34 vicky volumio[670]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Feb 17 19:17:34 vicky volumio[670]: at WebSocket.emit (events.js:315:20) Feb 17 19:17:34 vicky volumio[670]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 17 19:17:34 vicky volumio[670]: at Receiver.emit (events.js:315:20) Feb 17 19:17:34 vicky volumio[670]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 17 19:17:34 vicky volumio[670]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 17 19:17:34 vicky volumio[670]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 17 19:17:34 vicky volumio[670]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 17 19:17:34 vicky volumio[670]: at writeOrBuffer (internal/streams/writable.js:358:12) Feb 17 19:17:34 vicky volumio[670]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Feb 17 19:17:34 vicky volumio[670]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 17 19:17:34 vicky volumio[670]: at Socket.emit (events.js:315:20) Feb 17 19:17:34 vicky volumio[670]: at addChunk (internal/streams/readable.js:309:12) Feb 17 19:17:34 vicky volumio[670]: at readableAddChunk (internal/streams/readable.js:284:9) Feb 17 19:17:34 vicky volumio[670]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched first chunk of 18, total size is 9059720 bytes" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=info msg="prefetched track \"Modern Chemistry\" (duration: 230213ms)" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched first chunk of 16, total size is 8258956 bytes" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=info msg="loaded track \"Katie Queen of Tennessee\" (paused: false, position: 0ms, duration: 208333ms, prefetched: false)" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:0R0QQMC6StQ78L2LKeVozG" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:34 vicky go-librespot[974]: time="2026-02-17T19:17:34Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4mT7rUXqBdj7fgOY1D4prp" Feb 17 19:17:35 vicky sudo[1086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-17 19:16 Feb 17 19:17:35 vicky sudo[1086]: 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="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Feb 2026 01:46:18 PM CET" VOLUMIO_VERSION="3.908" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3e9dbaf8f44792d26e97456a18f12823"