Aug 29 15:16:09 volumio ntpd[929]: CLOCK: time stepped by 18921.426636 Aug 29 15:16:09 volumio ntpd[929]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 29 15:16:09 volumio avahi-daemon[1343]: Server startup complete. Host name is volumio.local. Local service cookie is 1728558214. Aug 29 15:16:10 volumio winbindd[1220]: [2026/08/29 15:16:10.179514, 0] ../../source3/winbindd/winbindd_idmap.c:372(wb_parent_idmap_setup_lookupname_done) Aug 29 15:16:10 volumio winbindd[1220]: wb_parent_idmap_setup_lookupname_done: Lookup domain name 'VOLUMIO' failed 'NT_STATUS_IO_TIMEOUT' Aug 29 15:16:10 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Aug 29 15:16:10 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Aug 29 15:16:10 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Aug 29 15:16:10 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Aug 29 15:16:10 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Aug 29 15:16:10 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Aug 29 15:16:10 volumio systemd[1]: Startup finished in 19.086s (kernel) + 34.412s (userspace) = 53.498s. Aug 29 15:16:10 volumio volumio[1119]: info: MYVOLUMIO Environment detected Aug 29 15:16:10 volumio sh[638]: timed out Aug 29 15:16:10 volumio dhcpcd[647]: timed out Aug 29 15:16:10 volumio sh[565]: ifup: failed to bring up eth0 Aug 29 15:16:10 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Aug 29 15:16:10 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Aug 29 15:16:10 volumio volumio[1119]: info: Plugin folders cleanup Aug 29 15:16:10 volumio volumio[1119]: info: Scanning into folder /volumio/app/plugins/ Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category audio_interface Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category miscellanea Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category music_service Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category plugins.json Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category system_controller Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category user_interface Aug 29 15:16:10 volumio volumio[1119]: info: Scanning into folder /data/plugins/ Aug 29 15:16:10 volumio volumio[1119]: info: Scanning category music_service Aug 29 15:16:10 volumio volumio[1119]: info: Plugin folders cleanup completed Aug 29 15:16:10 volumio volumio[1119]: info: ------------------------------------------- Aug 29 15:16:10 volumio volumio[1119]: info: ----- Core plugins startup ---- Aug 29 15:16:10 volumio volumio[1119]: info: ------------------------------------------- Aug 29 15:16:11 volumio volumio[1119]: info: Loading plugins from folder /volumio/app/plugins/ Aug 29 15:16:11 volumio volumio[1119]: info: Adding plugin upnp to MyMusic Plugins Aug 29 15:16:11 volumio volumio[1119]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 29 15:16:11 volumio volumio[1119]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 29 15:16:11 volumio volumio[1119]: info: Loading plugins from folder /data/plugins/ Aug 29 15:16:11 volumio volumio[1119]: info: Loading plugin "system"... Aug 29 15:16:11 volumio volumio[1119]: info: Loading plugin "appearance"... Aug 29 15:16:12 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 29 15:16:12 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 29 15:16:12 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 29 15:16:12 volumio upmpdcli[1388]: Could not open config: /tmp/upmpdcli.conf Aug 29 15:16:12 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 29 15:16:12 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "network"... Aug 29 15:16:13 volumio volumio[1119]: info: Refreshing Cached IP Addresses Aug 29 15:16:13 volumio sudo[1391]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 15:16:13 volumio sudo[1392]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 15:16:13 volumio sudo[1391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:13 volumio sudo[1392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:13 volumio sudo[1392]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:13 volumio sudo[1391]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "services"... Aug 29 15:16:13 volumio sudo[1401]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 29 15:16:13 volumio sudo[1401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "volumio5onboarding"... Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "alsa_controller"... Aug 29 15:16:13 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "wizard"... Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "networkfs"... Aug 29 15:16:13 volumio volumio[1119]: info: Starting Udev Watcher for removable devices Aug 29 15:16:13 volumio volumio[1119]: info: Ignoring mount for partition: boot Aug 29 15:16:13 volumio volumio[1119]: info: Ignoring mount for partition: volumio Aug 29 15:16:13 volumio volumio[1119]: info: Ignoring mount for partition: volumio_data Aug 29 15:16:13 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "volumio_command_line_client"... Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "upnp"... Aug 29 15:16:13 volumio volumio[1119]: info: [1788009373826] Starting Upmpd Daemon Aug 29 15:16:13 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "my_music"... Aug 29 15:16:13 volumio sudo[1426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=chef,password=kameLen10,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.68.107/music /mnt/NAS/Mijn_muziek Aug 29 15:16:13 volumio volumio[1119]: info: Loading plugin "mpd"... Aug 29 15:16:13 volumio sudo[1426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:13 volumio kernel: netfs: FS-Cache loaded Aug 29 15:16:14 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 29 15:16:14 volumio kernel: Key type cifs.spnego registered Aug 29 15:16:14 volumio kernel: Key type cifs.idmap registered Aug 29 15:16:14 volumio 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. Aug 29 15:16:14 volumio kernel: CIFS: Attempting to mount //192.168.68.107/music Aug 29 15:16:14 volumio volumio[1119]: info: Loading plugin "upnp_browser"... Aug 29 15:16:15 volumio sudo[1426]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:16 volumio volumio[1119]: info: Starting UPNP Browser Aug 29 15:16:16 volumio volumio[1119]: info: Loading plugin "alarm-clock"... Aug 29 15:16:16 volumio volumio[1119]: info: Loading plugin "airplay_emulation"... Aug 29 15:16:16 volumio volumio[1119]: info: Starting Shairport Sync Aug 29 15:16:16 volumio volumio[1119]: info: Loading plugin "last_100"... Aug 29 15:16:16 volumio volumio[1119]: info: Loading plugin "webradio"... Aug 29 15:16:17 volumio volumio[1119]: info: Loading plugin "i2s_dacs"... Aug 29 15:16:17 volumio volumio[1119]: info: I2S DAC not set, start Auto-detection Aug 29 15:16:17 volumio volumio[1119]: info: Loading plugin "volumiodiscovery"... Aug 29 15:16:17 volumio sudo[1401]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** For more information see Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 15:16:17 volumio volumio[1119]: *** WARNING *** For more information see Aug 29 15:16:17 volumio node[1119]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 15:16:17 volumio node[1119]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 15:16:17 volumio node[1119]: *** WARNING *** For more information see Aug 29 15:16:17 volumio node[1119]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 15:16:17 volumio node[1119]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 15:16:17 volumio node[1119]: *** WARNING *** For more information see Aug 29 15:16:17 volumio volumio[1119]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 29 15:16:17 volumio volumio[1119]: info: Discovery: Started advertising with name: Volumio Aug 29 15:16:17 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 15:16:17 volumio volumio[1119]: info: Loading plugin "spop"... Aug 29 15:16:19 volumio volumio-remote-updater[676]: [2026-08-29 15:16:19] [connect] Successful connection Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "outputs"... Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "albumart"... Aug 29 15:16:20 volumio volumio[1119]: info: Plugin example_plugin is not enabled Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "inputs"... Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "updater_comm"... Aug 29 15:16:20 volumio volumio[1119]: info: Plugin mpdemulation is not enabled Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "rest_api"... Aug 29 15:16:20 volumio volumio[1119]: info: Loading plugin "websocket"... Aug 29 15:16:20 volumio volumio[1119]: info: Starting Socket.io Server version 1.7.4 Aug 29 15:16:21 volumio volumio[1119]: info: Loading i18n strings for locale nl Aug 29 15:16:21 volumio volumio[1119]: Updating browse sources language Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::initPlayerControls Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: Express server listening on port 3000 Aug 29 15:16:21 volumio volumio[1119]: [Metrics] WebUI: 21s 41.79ms Aug 29 15:16:21 volumio volumio[1119]: info: CoreStateMachine::resetVolumioState Aug 29 15:16:21 volumio volumio[1119]: info: CoreStateMachine::getcurrentVolume Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 15:16:21 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:21 volumio volumio[1119]: info: Volumio Network Manager: Network status updated: 2 Aug 29 15:16:21 volumio volumio[1468]: Forking 3 albumart workers Aug 29 15:16:22 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 29 15:16:22 volumio volumio-remote-updater[676]: [2026-08-29 15:16:22] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788009379 101 Aug 29 15:16:22 volumio volumio[1119]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Aug 29 15:16:22 volumio volumio[1119]: info: Reloading queue from file Aug 29 15:16:22 volumio volumio[1119]: info: VolumeController:: Volume=33 Mute =false Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::pushState Aug 29 15:16:23 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:23 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 15:16:23 volumio volumio[1119]: info: CoreCommandRouter::volumioPushState Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::updateTrackBlock Aug 29 15:16:23 volumio volumio[1119]: info: CorePlayQueue::getTrackBlock Aug 29 15:16:23 volumio volumio[1119]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::setRepeat null single undefined Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::pushState Aug 29 15:16:23 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:23 volumio volumio[1119]: info: CoreCommandRouter::volumioPushState Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::setRandom null Aug 29 15:16:23 volumio volumio[1119]: info: CoreStateMachine::pushState Aug 29 15:16:23 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:23 volumio volumio[1119]: info: CoreCommandRouter::volumioPushState Aug 29 15:16:23 volumio volumio[1119]: info: Setting Device type: Raspberry PI Aug 29 15:16:24 volumio sudo[1553]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 15:16:24 volumio sudo[1553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:24 volumio sudo[1553]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:24 volumio volumio[1119]: info: Discovery: adding 3dec3835-e5e7-46c7-ac9b-2e093f6de2d5 Aug 29 15:16:24 volumio volumio[1119]: info: Discovery: Found device Volumio Aug 29 15:16:24 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:24 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:24 volumio volumio[1119]: info: Discovery: this is already registered, 3dec3835-e5e7-46c7-ac9b-2e093f6de2d5 Aug 29 15:16:24 volumio volumio[1119]: info: Discovery: Found device Volumio Aug 29 15:16:24 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:24 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:24 volumio volumio[1119]: info: VolumeController:: Volume=33 Mute =false Aug 29 15:16:24 volumio volumio[1119]: info: CoreStateMachine::pushState Aug 29 15:16:24 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:24 volumio volumio[1119]: info: CoreCommandRouter::volumioPushState Aug 29 15:16:24 volumio sudo[1555]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 15:16:24 volumio sudo[1555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:24 volumio sudo[1555]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:24 volumio volumio[1119]: info: Completed loading Core Plugins Aug 29 15:16:24 volumio volumio[1119]: info: Preparing to generate the ALSA configuration file Aug 29 15:16:24 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 29 15:16:24 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 29 15:16:24 volumio systemd[1]: setdatetime-helper.service: Consumed 1.265s CPU time. Aug 29 15:16:24 volumio sudo[1570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 29 15:16:24 volumio sudo[1570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:25 volumio volumio[1119]: info: Asound.conf file unchanged, so no further update is needed Aug 29 15:16:25 volumio volumio[1119]: info: Output device has changed, restarting MPD Aug 29 15:16:25 volumio volumio[1119]: info: Output device has changed, restarting Shairport Sync Aug 29 15:16:25 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:25 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:25 volumio sudo[1573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 15:16:25 volumio sudo[1573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:25 volumio sudo[1575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 15:16:25 volumio sudo[1575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:25 volumio sudo[1573]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:25 volumio volumio[1119]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 15:16:25 volumio volumio[1119]: info: ___________ START PLUGINS ___________ Aug 29 15:16:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 15:16:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 15:16:25 volumio volumio[1119]: info: ControllerMpd::onStart: Initializing MPD Aug 29 15:16:25 volumio volumio[1119]: info: Creating MPD Configuration file Aug 29 15:16:25 volumio sudo[1584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 29 15:16:25 volumio sudo[1584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:25 volumio sudo[1585]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 15:16:25 volumio sudo[1585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 29 15:16:25 volumio sudo[1589]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 29 15:16:25 volumio sudo[1585]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:25 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 15:16:25 volumio sudo[1592]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 15:16:25 volumio sudo[1592]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:25 volumio volumio[1119]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 15:16:25 volumio volumio[1119]: info: [1788009385943] CoreMusicLibrary::Adding element Media Servers Aug 29 15:16:25 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 15:16:25 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 29 15:16:26 volumio sudo[1584]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:26 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 29 15:16:26 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 29 15:16:26 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 29 15:16:26 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 29 15:16:26 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 29 15:16:26 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 15:16:26 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 15:16:26 volumio sudo[1587]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 15:16:26 volumio volumio[1119]: info: UPNP Browser: Client initialized successfully Aug 29 15:16:26 volumio sudo[1587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:26 volumio sudo[1587]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:26 volumio sudo[1596]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 15:16:26 volumio sudo[1596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 29 15:16:26 volumio sudo[1608]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 29 15:16:26 volumio sudo[1596]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:26 volumio volumio[1119]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:26 volumio volumio[1119]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 15:16:26 volumio volumio[1119]: info: [1788009386636] CoreMusicLibrary::Adding element Last_100 Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 15:16:26 volumio volumio[1119]: info: [1788009386642] CoreMusicLibrary::Adding element Webradio Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 15:16:26 volumio volumio[1119]: info: Initializing BBC Radios Aug 29 15:16:26 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:26.766+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 15:16:26 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:27 volumio volumio[1119]: info: Creating Spotify config file Aug 29 15:16:27 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:27 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 29 15:16:27 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 29 15:16:28 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 29 15:16:28 volumio sudo[1570]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:30 volumio volumio[1119]: info: Volumio Calling Home Aug 29 15:16:32 volumio volumio[1484]: Starting albumart workers Aug 29 15:16:33 volumio volumio[1482]: Starting albumart workers Aug 29 15:16:33 volumio volumio[1483]: Starting albumart workers Aug 29 15:16:33 volumio volumio[1119]: info: MPD Permissions set Aug 29 15:16:33 volumio volumio[1119]: info: MPD Permissions set Aug 29 15:16:33 volumio volumio[1119]: info: Upmpdcli Daemon Started Aug 29 15:16:33 volumio volumio[1119]: 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: 2 Aug 29 15:16:33 volumio mpd[1609]: 2026-08-29T15:16:33 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 15:16:34 volumio volumio[1119]: info: Volumio called home Aug 29 15:16:34 volumio volumio[1119]: info: Spotify config file written Aug 29 15:16:34 volumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 29 15:16:34 volumio sudo[1575]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:34 volumio sudo[1592]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:34 volumio volumio[1119]: 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: 2 Aug 29 15:16:34 volumio sudo[1660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 15:16:34 volumio sudo[1660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:34 volumio volumio[1119]: info: Received Get System Info Aug 29 15:16:34 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 15:16:34 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 15:16:34 volumio volumio[1119]: info: Discovery: Getting this device information Aug 29 15:16:34 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:34 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:34 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 15:16:34 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:34.515+02:00 level=INFO msg="system info for 64b6cf8e9975ad4d0965af140bb2ed17" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 29 15:16:34 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:34.542+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 29 15:16:34 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 29 15:16:34 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 29 15:16:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 15:16:34 volumio go-librespot[1668]: go-librespot daemon starting... Aug 29 15:16:34 volumio sudo[1660]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:35 volumio go-librespot[1669]: time="2026-08-29T15:16:35+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 15:16:35 volumio go-librespot[1669]: time="2026-08-29T15:16:35+02:00" level=debug msg="app state loaded" Aug 29 15:16:35 volumio go-librespot[1669]: time="2026-08-29T15:16:35+02:00" level=debug msg="stored credentials not found" Aug 29 15:16:35 volumio go-librespot[1669]: time="2026-08-29T15:16:35+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 15:16:36 volumio go-librespot[1669]: time="2026-08-29T15:16:36+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 15:16:36 volumio go-librespot[1669]: time="2026-08-29T15:16:36+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 29 15:16:36 volumio go-librespot[1669]: time="2026-08-29T15:16:36+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 29 15:16:36 volumio go-librespot[1669]: time="2026-08-29T15:16:36+02:00" level=info msg="zeroconf server listening on port 39615" Aug 29 15:16:36 volumio go-librespot[1669]: time="2026-08-29T15:16:36+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 15:16:36 volumio volumio[1119]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:36 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 15:16:37 volumio volumio[1119]: info: No need to fix Spotify hosts Aug 29 15:16:37 volumio volumio[1119]: info: Received Get System Info Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 15:16:37 volumio volumio[1119]: info: Discovery: Getting this device information Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:37 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:37 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 15:16:38 volumio volumio[1119]: info: Completed starting Core Plugins Aug 29 15:16:38 volumio volumio[1119]: info: ------------------------------------------- Aug 29 15:16:38 volumio volumio[1119]: info: ----- MyVolumio plugins startup ---- Aug 29 15:16:38 volumio volumio[1119]: info: ------------------------------------------- Aug 29 15:16:38 volumio volumio[1119]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 29 15:16:38 volumio volumio-remote-updater[676]: Test mode disabled Aug 29 15:16:38 volumio volumio-remote-updater[676]: Alpha mode disabled Aug 29 15:16:38 volumio volumio-remote-updater[676]: Alpha legacy test mode disabled Aug 29 15:16:39 volumio volumio[1119]: info: New Spotify access tokenBQDjVTLQ-Q... Aug 29 15:16:39 volumio volumio[1119]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 29 15:16:39 volumio volumio[1119]: error: MPD error: The expression evaluated to a falsy value: Aug 29 15:16:39 volumio volumio[1119]: assert.ok(self.idling) Aug 29 15:16:39 volumio volumio[1119]: error: The expression evaluated to a falsy value: Aug 29 15:16:39 volumio volumio[1119]: assert.ok(self.idling) Aug 29 15:16:39 volumio volumio[1119]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 29 15:16:39 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 29 15:16:39 volumio volumio[1119]: info: MPD running with PID1609 Aug 29 15:16:39 volumio volumio[1119]: ,establishing connection Aug 29 15:16:39 volumio volumio[1119]: info: Starting Shairport Sync Aug 29 15:16:39 volumio volumio[1119]: info: Starting Shairport Sync Aug 29 15:16:39 volumio volumio[1119]: info: Starting Shairport Sync Aug 29 15:16:39 volumio volumio[1119]: error: updateQueue error: null Aug 29 15:16:39 volumio sudo[1715]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 15:16:39 volumio sudo[1713]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 15:16:39 volumio sudo[1713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:39 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 15:16:39 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:39.789+02:00 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" Aug 29 15:16:39 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:39.791+02:00 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" Aug 29 15:16:39 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:39.791+02:00 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" Aug 29 15:16:39 volumio sudo[1715]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 15:16:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 15:16:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:39 volumio systemd[1]: shairport-sync.service: Consumed 1.661s CPU time. Aug 29 15:16:39 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 15:16:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:39 volumio sudo[1717]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 15:16:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 15:16:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 15:16:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:39 volumio sudo[1713]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:39 volumio sudo[1715]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:40 volumio sudo[1717]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 15:16:40 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 15:16:40 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 15:16:40 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:40 volumio volumio[1119]: error: updateQueue error: null Aug 29 15:16:40 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 15:16:40 volumio sudo[1717]: pam_unix(sudo:session): session closed for user root Aug 29 15:16:40 volumio volumio[1119]: info: Shairport-Sync Started Aug 29 15:16:40 volumio volumio[1119]: Error adding Membership: Error: addMembership EINVAL Aug 29 15:16:40 volumio volumio[1119]: info: Shairport-Sync Started Aug 29 15:16:40 volumio volumio[1119]: info: Received Get System Info Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 15:16:40 volumio volumio[1119]: info: Discovery: Getting this device information Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:40 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 15:16:40 volumio volumio[1119]: info: Shairport-Sync Started Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 15:16:40 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:40.451+02:00 level=INFO msg="enabling local network discovery" Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:16:40 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:16:40 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:40.471+02:00 level=INFO msg="enabling BLE discovery" Aug 29 15:16:40 volumio volumio[1119]: info: Spotify Successfully logged in Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 15:16:40 volumio volumio[1119]: info: [1788009400651] CoreMusicLibrary::Adding element Spotify Aug 29 15:16:40 volumio volumio[1119]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 15:16:40 volumio volumio[1119]: Cannot find translation for source Spotify Aug 29 15:16:41 volumio volumio5-onboarding[1594]: time=2026-08-29T15:16:41.483+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 29 15:16:41 volumio volumio[1119]: info: go-librespot daemon successfully initialized Aug 29 15:16:44 volumio volumio[1119]: info: Initializing connection to go-librespot Websocket Aug 29 15:16:44 volumio volumio[1119]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 29 15:16:49 volumio go-librespot[1669]: time="2026-08-29T15:16:49+02:00" level=debug msg="new websocket client" Aug 29 15:16:52 volumio volumio[1119]: info: Connection to go-librespot Websocket established Aug 29 15:16:53 volumio go-librespot[1669]: time="2026-08-29T15:16:53+02:00" level=debug msg="obtained new client token: AAFOdVjWBFAoaXP4qgKegX6h/VgqtSnYoXHQq4Qes0dz4ib6ftAklIdSNnqQspKxYGQ7ykJThDD1VvvZTJFqChi1gMc+0agQQX6XYK27vs/7u2IRP4wG/fod+wWlmcqxc+A2Pf4K6b+4a+BcxIQZHLnWQNTlt/XtA9XW/q0LK9y7lh4JX9W49t1sTIuCw2kJdfe+SlamNPm1gCfga5ddJW6DjTh+VXX5Hs0GuBEuLOmOTaM44ibDAg==" Aug 29 15:16:53 volumio go-librespot[1669]: time="2026-08-29T15:16:53+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="completed keyexchange" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="completed challenge" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=info msg="authenticated AP" username="gr********os" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=info msg="authenticated Login5" username="gr********os" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=info msg="accepted zeroconf from Pixel 6a" username="gr********os" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="dealer connection opened" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="starting accesspoint recv loop" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="starting dealer recv loop" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="received accesspoint ping" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="received connection id: Nzk4YTNjMDQtOGQ1...QzdEMkQzRkNCQQ==" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="received accesspoint pong ack" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="put connect state because NEW_DEVICE" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="handling transfer player command from 1d124534d5e998ae4acc7de51cf6e1c49f76b0a2" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:24dNz3biIGWclErCSsACgc" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="fetched new page 0 with 33 items (list: 33)" uri="spotify:playlist:24dNz3biIGWclErCSsACgc" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="shuffled context with seed 15904488225995553798 (len: 33, keep: 25)" uri="spotify:playlist:24dNz3biIGWclErCSsACgc" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="loading track (paused: false, position: 2832ms)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=trace msg="emitting websocket event: will_play" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="selected format OGG_VORBIS_320 (c33faf85b44f1718cd7515e5685758965ab33480)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:54 volumio go-librespot[1669]: time="2026-08-29T15:16:54+02:00" level=debug msg="requested aes key for file c33faf85b44f1718cd7515e5685758965ab33480, gid: 3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1804" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="fetched first chunk of 16, total size is 8215270 bytes" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="seek to 2832ms (diff: 129ms, samples: 124891, bytes: 108149)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="created new output device" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" 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" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=info msg="loaded track \"Das Model\" (paused: false, position: 2832ms, duration: 219606ms, prefetched: false)" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1404" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="scheduling prefetch in 187s" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="emitting websocket event: active" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=trace msg="emitting websocket event: playing" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:55 volumio go-librespot[1669]: time="2026-08-29T15:16:55+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:16:56 volumio volumio[1119]: info: Getting Spotify volume Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="update volume requested to 62914/65535" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="update volume requested to 60292/65535" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="update volume requested to 41942/65535" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:16:58 volumio go-librespot[1669]: time="2026-08-29T15:16:58+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:16:59 volumio go-librespot[1669]: time="2026-08-29T15:16:59+02:00" level=debug msg="update volume requested to 31457/65535" Aug 29 15:16:59 volumio go-librespot[1669]: time="2026-08-29T15:16:59+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:16:59 volumio go-librespot[1669]: time="2026-08-29T15:16:59+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:17:00 volumio volumio[1119]: info: Aligning Spotify Volume to Volumio Volume Aug 29 15:17:00 volumio volumio[1119]: info: CoreCommandRouter::volumioGetState Aug 29 15:17:00 volumio volumio[1119]: info: CorePlayQueue::getTrack 0 Aug 29 15:17:00 volumio volumio[1119]: info: Setting Spotify Volume from Volumio: 33 Aug 29 15:17:00 volumio volumio[1119]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 15:17:00 volumio go-librespot[1669]: time="2026-08-29T15:17:00+02:00" level=debug msg="update volume requested to 28835/65535" Aug 29 15:17:00 volumio volumio[1119]: TypeError: Cannot read properties of undefined (reading 'service') Aug 29 15:17:00 volumio volumio[1119]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:345:50) Aug 29 15:17:00 volumio volumio[1119]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Aug 29 15:17:00 volumio volumio[1119]: at WebSocket.message (/data/plugins/music_service/spop/index.js:198:14) Aug 29 15:17:00 volumio volumio[1119]: at WebSocket.emit (node:events:514:28) Aug 29 15:17:00 volumio volumio[1119]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1239:20) Aug 29 15:17:00 volumio volumio[1119]: at Receiver.emit (node:events:514:28) Aug 29 15:17:00 volumio volumio[1119]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:633:14) Aug 29 15:17:00 volumio volumio[1119]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:532:10) Aug 29 15:17:00 volumio volumio[1119]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:190:16) Aug 29 15:17:00 volumio volumio[1119]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:117:10) Aug 29 15:17:00 volumio volumio[1119]: at writeOrBuffer (node:internal/streams/writable:399:12) Aug 29 15:17:00 volumio volumio[1119]: at _write (node:internal/streams/writable:340:10) Aug 29 15:17:00 volumio volumio[1119]: at Writable.write (node:internal/streams/writable:344:10) Aug 29 15:17:00 volumio volumio[1119]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1374:35) Aug 29 15:17:00 volumio volumio[1119]: at Socket.emit (node:events:514:28) Aug 29 15:17:00 volumio volumio[1119]: at addChunk (node:internal/streams/readable:343:12) Aug 29 15:17:00 volumio volumio[1119]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 15:17:00 volumio go-librespot[1669]: time="2026-08-29T15:17:00+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:17:00 volumio go-librespot[1669]: time="2026-08-29T15:17:00+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:17:00 volumio go-librespot[1669]: time="2026-08-29T15:17:00+02:00" level=debug msg="update volume requested to 26214/65535" Aug 29 15:17:01 volumio go-librespot[1669]: time="2026-08-29T15:17:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:17:01 volumio go-librespot[1669]: time="2026-08-29T15:17:01+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:17:01 volumio go-librespot[1669]: time="2026-08-29T15:17:01+02:00" level=debug msg="update volume requested to 10486/65535" Aug 29 15:17:01 volumio go-librespot[1669]: time="2026-08-29T15:17:01+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 15:17:01 volumio go-librespot[1669]: time="2026-08-29T15:17:01+02:00" level=trace msg="emitting websocket event: volume" Aug 29 15:17:05 volumio volumio5-onboarding[1594]: time=2026-08-29T15:17:05.849+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.68.100:52714 Aug 29 15:17:05 volumio go-librespot[1669]: time="2026-08-29T15:17:05+02:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:3VwLD5o1r0YBLkjUfgSEYg" Aug 29 15:17:05 volumio volumio5-onboarding[1594]: time=2026-08-29T15:17:05.894+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.68.100:52714 @ 0x2801560" latency=-1.072173451s platform=PLATFORM_ANDROID version=6.260807.0 Aug 29 15:17:05 volumio volumio5-onboarding[1594]: time=2026-08-29T15:17:05.904+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.68.100:52714 @ 0x2801560" latency=-1.061007911s timeout=20s Aug 29 15:17:05 volumio volumio5-onboarding[1594]: time=2026-08-29T15:17:05.904+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.68.100:52714 @ 0x2801560" Aug 29 15:17:06 volumio sudo[1819]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 15:16' Aug 29 15:17:06 volumio sudo[1819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"