-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2026-06-02 18:23:52 CEST. -- Jun 02 18:22:01 volumio systemd-timedated[915]: Changed local time to Tue Jun 2 18:22:01 2026 Jun 02 18:22:01 volumio sudo[913]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:01 volumio volumio-time-update[629]: volumio-time-update-util: System time updated successfully. Jun 02 18:22:01 volumio systemd[1]: Starting Daily apt download activities... Jun 02 18:22:01 volumio systemd[1]: Started Volumio Time Update Utility. Jun 02 18:22:01 volumio ntpd[783]: Listen normally on 3 eth0 192.168.0.130:123 Jun 02 18:22:01 volumio ntpd[783]: new interface(s) found: waking up resolver Jun 02 18:22:03 volumio systemd[1]: apt-daily.service: Succeeded. Jun 02 18:22:03 volumio systemd[1]: Started Daily apt download activities. Jun 02 18:22:03 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jun 02 18:22:03 volumio nmbd[751]: [2026/06/02 18:22:03.584565, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 02 18:22:03 volumio systemd[1]: Started Samba NMB Daemon. Jun 02 18:22:03 volumio nmbd[751]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jun 02 18:22:03 volumio systemd[1]: Starting Samba Winbind Daemon... Jun 02 18:22:03 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 02 18:22:03 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jun 02 18:22:04 volumio winbindd[994]: [2026/06/02 18:22:04.088306, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jun 02 18:22:04 volumio winbindd[994]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jun 02 18:22:04 volumio winbindd[994]: [2026/06/02 18:22:04.539177, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 02 18:22:04 volumio systemd[1]: Started Samba Winbind Daemon. Jun 02 18:22:04 volumio winbindd[994]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jun 02 18:22:04 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:04 volumio volumio[890]: info: ----- Volumio3 ---- Jun 02 18:22:04 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:04 volumio volumio[890]: info: ----- System startup ---- Jun 02 18:22:04 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:04 volumio systemd[1]: Starting Samba SMB Daemon... Jun 02 18:22:07 volumio smbd[1026]: [2026/06/02 18:22:07.160007, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 02 18:22:07 volumio systemd[1]: Started Samba SMB Daemon. Jun 02 18:22:07 volumio smbd[1026]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 02 18:22:07 volumio systemd[1]: Reached target Multi-User System. Jun 02 18:22:07 volumio systemd[1]: Reached target Graphical Interface. Jun 02 18:22:07 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 02 18:22:07 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 02 18:22:07 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 02 18:22:07 volumio systemd[1]: Startup finished in 16.732s (kernel) + 20.169s (userspace) = 36.901s. Jun 02 18:22:07 volumio volumio[890]: info: MYVOLUMIO Environment detected Jun 02 18:22:07 volumio volumio-remote-updater[641]: [2026-06-02 18:22:07] [connect] Successful connection Jun 02 18:22:07 volumio volumio[890]: info: Plugin folders cleanup Jun 02 18:22:07 volumio volumio[890]: info: Scanning into folder /volumio/app/plugins/ Jun 02 18:22:07 volumio volumio[890]: info: Scanning category audio_interface Jun 02 18:22:07 volumio volumio[890]: info: Scanning category miscellanea Jun 02 18:22:07 volumio volumio[890]: info: Scanning category music_service Jun 02 18:22:07 volumio volumio[890]: info: Scanning category plugins.json Jun 02 18:22:07 volumio volumio[890]: info: Scanning category system_controller Jun 02 18:22:07 volumio volumio[890]: info: Scanning category user_interface Jun 02 18:22:07 volumio volumio[890]: info: Scanning into folder /data/plugins/ Jun 02 18:22:07 volumio volumio[890]: info: Scanning category audio_interface Jun 02 18:22:07 volumio volumio[890]: info: Scanning category music_service Jun 02 18:22:07 volumio volumio[890]: info: Scanning category system_controller Jun 02 18:22:07 volumio volumio[890]: info: Scanning category user_interface Jun 02 18:22:07 volumio volumio[890]: info: Plugin folders cleanup completed Jun 02 18:22:07 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:07 volumio volumio[890]: info: ----- Core plugins startup ---- Jun 02 18:22:07 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:07 volumio volumio[890]: info: Loading plugins from folder /volumio/app/plugins/ Jun 02 18:22:07 volumio volumio[890]: info: Adding plugin upnp to MyMusic Plugins Jun 02 18:22:07 volumio volumio[890]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 02 18:22:07 volumio volumio[890]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 02 18:22:07 volumio volumio[890]: info: Loading plugins from folder /data/plugins/ Jun 02 18:22:07 volumio volumio[890]: info: Loading plugin "system"... Jun 02 18:22:07 volumio volumio[890]: info: Loading plugin "appearance"... Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "network"... Jun 02 18:22:09 volumio volumio[890]: info: Refreshing Cached IP Addresses Jun 02 18:22:09 volumio sudo[1041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:22:09 volumio sudo[1041]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "services"... Jun 02 18:22:09 volumio sudo[1043]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:22:09 volumio sudo[1041]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "volumio5onboarding"... Jun 02 18:22:09 volumio sudo[1043]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:09 volumio sudo[1043]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "alsa_controller"... Jun 02 18:22:09 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "wizard"... Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "networkfs"... Jun 02 18:22:09 volumio volumio[890]: info: Starting Udev Watcher for removable devices Jun 02 18:22:09 volumio sudo[1066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=mm,password=882otgmm###,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.101/audio /mnt/NAS/audio Jun 02 18:22:09 volumio sudo[1066]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:09 volumio volumio[890]: info: Ignoring mount for partition: boot Jun 02 18:22:09 volumio volumio[890]: info: Ignoring mount for partition: volumio Jun 02 18:22:09 volumio volumio[890]: info: Ignoring mount for partition: volumio_data Jun 02 18:22:09 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "volumio_command_line_client"... Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "upnp"... Jun 02 18:22:09 volumio volumio[890]: info: [1780417329977] Starting Upmpd Daemon Jun 02 18:22:09 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:22:09 volumio volumio[890]: info: Loading plugin "my_music"... Jun 02 18:22:10 volumio volumio[890]: info: Loading plugin "mpd"... Jun 02 18:22:10 volumio kernel: Key type cifs.spnego registered Jun 02 18:22:10 volumio kernel: Key type cifs.idmap registered Jun 02 18:22:10 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. Jun 02 18:22:10 volumio kernel: CIFS: Attempting to mount //192.168.0.101/audio Jun 02 18:22:10 volumio sudo[1066]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:10 volumio volumio[890]: info: Loading plugin "upnp_browser"... Jun 02 18:22:11 volumio volumio[890]: info: Starting UPNP Browser Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "alarm-clock"... Jun 02 18:22:11 volumio volumio[890]: info: Plugin airplay_emulation is not enabled Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "last_100"... Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "webradio"... Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "i2s_dacs"... Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "volumiodiscovery"... Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** For more information see Jun 02 18:22:11 volumio node[890]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:22:11 volumio volumio[890]: *** WARNING *** For more information see Jun 02 18:22:11 volumio node[890]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:22:11 volumio node[890]: *** WARNING *** For more information see Jun 02 18:22:11 volumio node[890]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:22:11 volumio node[890]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:22:11 volumio node[890]: *** WARNING *** For more information see Jun 02 18:22:11 volumio volumio[890]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 02 18:22:11 volumio volumio[890]: info: Discovery: Started advertising with name: Volumio Jun 02 18:22:11 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:22:11 volumio volumio[890]: info: Loading plugin "spop"... Jun 02 18:22:16 volumio volumio[890]: info: Loading plugin "outputs"... Jun 02 18:22:16 volumio volumio[890]: info: Loading plugin "albumart"... Jun 02 18:22:16 volumio volumio[890]: info: Plugin example_plugin is not enabled Jun 02 18:22:16 volumio volumio[890]: info: Loading plugin "inputs"... Jun 02 18:22:16 volumio volumio[890]: info: Loading plugin "updater_comm"... Jun 02 18:22:17 volumio volumio[890]: info: Plugin mpdemulation is not enabled Jun 02 18:22:17 volumio volumio[890]: info: Loading plugin "rest_api"... Jun 02 18:22:17 volumio volumio[890]: info: Loading plugin "websocket"... Jun 02 18:22:17 volumio volumio[890]: info: Starting Socket.io Server version 2.3.0 Jun 02 18:22:17 volumio volumio[890]: info: Plugin fusiondsp is not enabled Jun 02 18:22:17 volumio volumio[890]: info: Loading plugin "backup_restore"... Jun 02 18:22:17 volumio volumio[890]: Forking 3 albumart workers Jun 02 18:22:17 volumio volumio[890]: info: Applying required configuration parameters for plugin backup_restore Jun 02 18:22:17 volumio volumio[890]: info: Loading plugin "Systeminfo"... Jun 02 18:22:18 volumio volumio[890]: Starting albumart workers Jun 02 18:22:18 volumio volumio[890]: Starting albumart workers Jun 02 18:22:18 volumio volumio[890]: Starting albumart workers Jun 02 18:22:18 volumio volumio[890]: info: Loading plugin "lastfm"... Jun 02 18:22:19 volumio volumio[890]: info: Loading i18n strings for locale de Jun 02 18:22:19 volumio volumio[890]: Updating browse sources language Jun 02 18:22:19 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::initPlayerControls Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:22:20 volumio volumio[890]: Express server listening on port 3000 Jun 02 18:22:20 volumio volumio[890]: [Metrics] WebUI: 17s 107.52ms Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::resetVolumioState Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::getcurrentVolume Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:22:20 volumio sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:22:20 volumio sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio sudo[1174]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio sudo[1176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:22:20 volumio sudo[1176]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio sudo[1176]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio volumio[890]: info: Volumio Network Manager: Network status updated: 1 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:20 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:20 volumio volumio[890]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jun 02 18:22:20 volumio volumio[890]: info: VolumeController:: Volume=10 Mute =false Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::updateTrackBlock Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrackBlock Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: Reloading queue from file Jun 02 18:22:20 volumio volumio[890]: info: Setting Device type: Raspberry PI Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::setRepeat false single undefined Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::setRandom null Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:20 volumio volumio[890]: info: Listing playlists Jun 02 18:22:20 volumio volumio[890]: info: Listing playlists Jun 02 18:22:20 volumio volumio[890]: info: Completed loading Core Plugins Jun 02 18:22:20 volumio volumio[890]: info: Preparing to generate the ALSA configuration file Jun 02 18:22:20 volumio volumio[890]: verbose: New Socket.io Connection to 192.168.0.130:3000 from 192.168.0.190 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 2 Jun 02 18:22:20 volumio sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 02 18:22:20 volumio sudo[1188]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio volumio[890]: info: VolumeController:: Volume=10 Mute =false Jun 02 18:22:20 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:20 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:20 volumio volumio[890]: info: Asound.conf file unchanged, so no further update is needed Jun 02 18:22:20 volumio volumio[890]: info: Output device has changed, restarting MPD Jun 02 18:22:20 volumio volumio[890]: info: ___________ START PLUGINS ___________ Jun 02 18:22:20 volumio sudo[1192]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:22:20 volumio sudo[1192]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jun 02 18:22:20 volumio volumio[890]: info: ControllerMpd::onStart: Initializing MPD Jun 02 18:22:20 volumio volumio[890]: info: Creating MPD Configuration file Jun 02 18:22:20 volumio sudo[1192]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio sudo[1194]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:22:20 volumio sudo[1194]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio sudo[1198]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 02 18:22:20 volumio sudo[1198]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio sudo[1188]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio sudo[1201]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:22:20 volumio sudo[1201]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:22:20 volumio sudo[1201]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio volumio[890]: info: [1780417340876] CoreMusicLibrary::Adding element Medienserver Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:20 volumio systemd[1]: Started Volumio5 Onboarding Server. Jun 02 18:22:20 volumio sudo[1203]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:22:20 volumio sudo[1203]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:20 volumio volumio[890]: info: UPNP Browser: Client initialized successfully Jun 02 18:22:20 volumio systemd[1]: Listening on mpd.socket. Jun 02 18:22:20 volumio systemd[1]: Starting Music Player Daemon... Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:22:20 volumio volumio[890]: info: [1780417340920] CoreMusicLibrary::Adding element Last_100 Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:22:20 volumio volumio[890]: info: [1780417340926] CoreMusicLibrary::Adding element Webradio Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:20 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:22:20 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Jun 02 18:22:20 volumio systemd[1]: mpd.service: Succeeded. Jun 02 18:22:20 volumio systemd[1]: Stopped Music Player Daemon. Jun 02 18:22:20 volumio sudo[1198]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:20 volumio volumio[890]: info: Initializing BBC Radios Jun 02 18:22:20 volumio systemd[1]: Starting Music Player Daemon... Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: Creating Spotify config file Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio sudo[1209]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 18:22:21 volumio sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:21 volumio sudo[1209]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jun 02 18:22:21 volumio sudo[1209]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:22:21 volumio volumio[890]: info: [1780417341156] CoreMusicLibrary::Adding element LastFM Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:21 volumio volumio[890]: Cannot find translation for source LastFM Jun 02 18:22:21 volumio volumio[890]: info: [LastFM] scrobbler initiated! Jun 02 18:22:21 volumio volumio[890]: info: [LastFM] extended logging: false Jun 02 18:22:21 volumio volumio[890]: info: [LastFM] try scrobble stream/radio plays: true Jun 02 18:22:21 volumio volumio[890]: info: [LastFM] Left init routine Jun 02 18:22:21 volumio volumio[890]: info: [LastFM] Socket already connected: true Jun 02 18:22:21 volumio volumio[890]: info: Volumio Calling Home Jun 02 18:22:21 volumio volumio[890]: info: Discovery: adding 198b4bbd-3d07-43db-9a28-8aeacee0c349 Jun 02 18:22:21 volumio volumio[890]: info: Discovery: Found device Volumio Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:21 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 02 18:22:21 volumio volumio[890]: info: MPD Permissions set Jun 02 18:22:21 volumio volumio[890]: info: MPD Permissions set Jun 02 18:22:21 volumio volumio[890]: info: Upmpdcli Daemon Started Jun 02 18:22:21 volumio volumio[890]: info: Spotify config file written Jun 02 18:22:21 volumio systemd[1]: systemd-fsckd.service: Succeeded. Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:21 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:22 volumio sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 18:22:22 volumio sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:22:22 volumio volumio[890]: info: No need to fix Spotify hosts Jun 02 18:22:22 volumio systemd[1]: Started go-librespot Daemon. Jun 02 18:22:22 volumio sudo[1231]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:22 volumio go-librespot[1241]: go-librespot daemon starting... Jun 02 18:22:22 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:22.628+02:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Jun 02 18:22:22 volumio volumio[890]: 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 Jun 02 18:22:22 volumio volumio[890]: 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 Jun 02 18:22:22 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:22 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:22 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:22 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:22.727+02:00 level=INFO msg="system info for 66f50257e5b2ed7a9f86301de519ee37" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=3.912 Jun 02 18:22:22 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:22 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:22 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 02 18:22:22 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:22.741+02:00 level=INFO msg="enabling local network discovery" Jun 02 18:22:22 volumio volumio-remote-updater[641]: [2026-06-02 18:22:22] [connect] Successful connection Jun 02 18:22:22 volumio volumio-remote-updater[641]: [2026-06-02 18:22:22] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1780417342 101 Jun 02 18:22:22 volumio volumio[890]: 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: 3 Jun 02 18:22:22 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:22.803+02:00 level=INFO msg="enabling BLE discovery" Jun 02 18:22:22 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:22.926+02:00 level=INFO msg="bootstrapping state" hasInternet=true Jun 02 18:22:22 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:22 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:22 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:22 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:22 volumio volumio-remote-updater[641]: No test mode Jun 02 18:22:22 volumio volumio-remote-updater[641]: No alpha test mode Jun 02 18:22:23 volumio volumio[890]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 02 18:22:23 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 02 18:22:23 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:23 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:23.108+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" Jun 02 18:22:23 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:23.109+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" Jun 02 18:22:23 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:23.110+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" Jun 02 18:22:23 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:23 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" level=info msg="running go-librespot 0.4.0" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" level=debug msg="app state loaded" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" 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]" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" 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]" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" 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]" Jun 02 18:22:23 volumio go-librespot[1241]: time="2026-06-02T18:22:23+02:00" level=info msg="zeroconf server listening on port 33037" Jun 02 18:22:24 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:24.084+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.190:35594 Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="obtained new client token: AAAYteYVNgZxKjk8pmHYFRui/0xq4XlKhred/RP2Z7zTAOmkDxKpuo+l/9eg9gUuYGIe4dtEkr3hia0MfGg0JMj0A6Vzqo+Hz67M8nQf7/g0Ciq4u/VydFrYUMskY24D1uRudvo4xCex8rKGuA/r43BmhC0ptykZ95x8Md7BMSINro8k9te8aOiPPbft/KzTyX2b5beRF1Bz2574U3ehZMSmxSQuaixLDH2Jxs9osR+YOueQh06SIFI=" Jun 02 18:22:24 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:24.124+02:00 level=INFO msg="service successfully established" component=discovery/localnet Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="completed keyexchange" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="completed challenge" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=info msg="authenticated AP" username="28***to" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=info msg="authenticated Login5" username="28***to" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="initializing zeroconf session" username="28***to" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="dealer connection opened" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=trace msg="starting accesspoint recv loop" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=trace msg="starting dealer recv loop" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=trace msg="received accesspoint ping" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="received connection id: NWMxYWRmNGYtNjZk...MkNEMUY3NTJEMg==" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=trace msg="received accesspoint pong ack" Jun 02 18:22:24 volumio go-librespot[1241]: time="2026-06-02T18:22:24+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 02 18:22:24 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:24.914+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.0.190:35594 Jun 02 18:22:24 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:24.914+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.0.190:35594 Jun 02 18:22:24 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:24.970+02:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.190:35614 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:25 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:25 volumio volumio[890]: info: go-librespot daemon successfully initialized Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.582+02:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.0.190:35614 @ 0x1801b60" latency=-843.441598ms platform=PLATFORM_ANDROID version=5.260413.0 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.586+02:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.190:35614 @ 0x1801b60" latency=-2.263841815s timeout=10s Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.586+02:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" Jun 02 18:22:25 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:25 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:25 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.597+02:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" name=Volumio Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.605+02:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" language=de Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.611+02:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" timezone=Europe/Vienna Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.612+02:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" available=true connected=true macAddress=b8:27:eb:5f:07:02 ip4Address=192.168.0.130/24 ip6Address= Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.614+02:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.615+02:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" setupComplete=true Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 02 18:22:25 volumio volumio[890]: amixer -c 2 info | grep "snd_rpi_hifiberry_dacplus" Jun 02 18:22:25 volumio volumio[890]: Card hw:2 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Jun 02 18:22:25 volumio volumio[890]: amixer -c 0 info | grep "bcm2835 ALSA" Jun 02 18:22:25 volumio volumio[890]: amixer -c 1 info | grep "bcm2835 Headphones" Jun 02 18:22:25 volumio volumio[890]: Card hw:1 'Headphones'/'bcm2835 Headphones' Jun 02 18:22:25 volumio volumio[890]: amixer -c 2 info | grep "snd_rpi_hifiberry_dacplus" Jun 02 18:22:25 volumio volumio[890]: Card hw:2 'sndrpihifiberry'/'snd_rpi_hifiberry_dacplus' Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.867+02:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" selectedOutputId=2 Jun 02 18:22:25 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:25 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:25 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.892+02:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" currentVersion=3.912 latestVersion=3.912 Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.893+02:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.190:35614 @ 0x1801b60" status=UPDATE_STATUS_NONE progress=0 Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.893+02:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" userId= Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.894+02:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" providers=3 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.899+02:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" plugins=0 Jun 02 18:22:25 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:25 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.907+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" state=STATUS_STOPPED positionMs=0 volume=10 Jun 02 18:22:25 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:25.908+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.190:35614 @ 0x1801b60" id=http://192.168.0.101:8200/MediaItems/232149.flac title="More Than a Feeling" Jun 02 18:22:26 volumio mpd[1221]: Jun 02 18:22 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 02 18:22:26 volumio volumio[890]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 02 18:22:26 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:26.198+02:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.190:35614 @ 0x1801b60" latency=-2.267394388s timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Jun 02 18:22:26 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:26 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:26 volumio volumio[890]: info: Volumio called home Jun 02 18:22:26 volumio volumio[890]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:22:26 volumio volumio[890]: SPOTIFY: BQDlHXITN_KcfvOssvZyMax9FeodvLEes4plR0kS3E6zCfanFR_murKrhcNlef6YM4vCyTXXxMpqgHCNcI_0FszmXcRSJDtxNRHrVz69QwMAutMtv96S605rqc2U4Yvw9eTINpG-pBUSEl9sKcDoK-AapHXhYFc6eEkFhK4McrrVhMGXYlLW_yY3k4EzXkNGb2rYXTkWn-OphW-2rpXqfSfqXbp3LnHGCwsvYM-N3Xx_t3eXBgiunWCyHiFsW8NQhgQc0z8JyyGiQS3WNnq1a7ED2RlJtpokAg Jun 02 18:22:26 volumio volumio[890]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:22:26 volumio volumio[890]: info: New Spotify access token = BQDlHXITN_KcfvOssvZyMax9FeodvLEes4plR0kS3E6zCfanFR_murKrhcNlef6YM4vCyTXXxMpqgHCNcI_0FszmXcRSJDtxNRHrVz69QwMAutMtv96S605rqc2U4Yvw9eTINpG-pBUSEl9sKcDoK-AapHXhYFc6eEkFhK4McrrVhMGXYlLW_yY3k4EzXkNGb2rYXTkWn-OphW-2rpXqfSfqXbp3LnHGCwsvYM-N3Xx_t3eXBgiunWCyHiFsW8NQhgQc0z8JyyGiQS3WNnq1a7ED2RlJtpokAg Jun 02 18:22:26 volumio volumio[890]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 02 18:22:26 volumio volumio[890]: info: [LastFM] finished init: Authenticated successfully! Jun 02 18:22:26 volumio volumio[890]: SPOTIFY: User informations: {"account_id":"Rf8p5ogBAa","country":"AT","display_name":"288 GTO","email":"288gto@gmx.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/288_gto"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/288_gto","id":"288_gto","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85467fa7ce35d304790fe5f608","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82467fa7ce35d304790fe5f608","width":64}],"product":"premium","type":"user","uri":"spotify:user:288_gto"} Jun 02 18:22:26 volumio volumio[890]: info: Spotify Successfully logged in Jun 02 18:22:26 volumio volumio[890]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:22:26 volumio volumio[890]: info: [1780417346688] CoreMusicLibrary::Adding element Spotify Jun 02 18:22:26 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:26 volumio volumio[890]: Cannot find translation for source LastFM Jun 02 18:22:26 volumio volumio[890]: Cannot find translation for source Spotify Jun 02 18:22:28 volumio systemd[1]: Started Music Player Daemon. Jun 02 18:22:28 volumio volumio[890]: Upnp client error: Error: This socket has been ended by the other party Jun 02 18:22:28 volumio volumio[890]: Upnp client error: Error: This socket has been ended by the other party Jun 02 18:22:28 volumio sudo[1194]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:28 volumio sudo[1203]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:28 volumio volumio[890]: info: Completed starting Core Plugins Jun 02 18:22:28 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:28 volumio volumio[890]: info: ----- MyVolumio plugins startup ---- Jun 02 18:22:28 volumio volumio[890]: info: ------------------------------------------- Jun 02 18:22:28 volumio volumio[890]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 02 18:22:28 volumio volumio[890]: info: MPD running with PID1221 Jun 02 18:22:28 volumio volumio[890]: ,establishing connection Jun 02 18:22:28 volumio volumio[890]: error: MPD error: The expression evaluated to a falsy value: Jun 02 18:22:28 volumio volumio[890]: assert.ok(self.idling) Jun 02 18:22:28 volumio volumio[890]: error: The expression evaluated to a falsy value: Jun 02 18:22:28 volumio volumio[890]: assert.ok(self.idling) Jun 02 18:22:28 volumio volumio[890]: error: MPD error: The expression evaluated to a falsy value: Jun 02 18:22:28 volumio volumio[890]: assert.ok(self.idling) Jun 02 18:22:28 volumio volumio[890]: error: The expression evaluated to a falsy value: Jun 02 18:22:28 volumio volumio[890]: assert.ok(self.idling) Jun 02 18:22:28 volumio volumio[890]: info: Initializing connection to go-librespot Websocket Jun 02 18:22:28 volumio volumio[890]: error: updateQueue error: null Jun 02 18:22:28 volumio go-librespot[1241]: time="2026-06-02T18:22:28+02:00" level=debug msg="new websocket client" Jun 02 18:22:28 volumio volumio[890]: info: Connection to go-librespot Websocket established Jun 02 18:22:29 volumio sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:22:29 volumio sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:29 volumio sudo[1275]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:29 volumio sudo[1277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:22:29 volumio sudo[1277]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:29 volumio sudo[1277]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:29 volumio volumio[890]: verbose: New Socket.io Connection to 192.168.0.130 from 192.168.0.190 UA: Mozilla/5.0 (Linux; Android 16; Pixel 9 Pro Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::volumioGetVisibleSources Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:29 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 02 18:22:29 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:29 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:29 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:29 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:29 volumio volumio[890]: info: Listing playlists Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 02 18:22:29 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 02 18:22:30 volumio sudo[1295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:22:30 volumio sudo[1295]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:30 volumio sudo[1295]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:30 volumio sudo[1297]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:22:30 volumio sudo[1297]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:30 volumio sudo[1297]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:30 volumio volumio[890]: verbose: New Socket.io Connection to 192.168.0.130 from 192.168.0.190 UA: Mozilla/5.0 (Linux; Android 16; Pixel 9 Pro Build/CP1A.260505.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/148.0.7778.178 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::volumioGetVisibleSources Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:30 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 02 18:22:30 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:30 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:30 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:30 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:30 volumio volumio[890]: info: Listing playlists Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 02 18:22:30 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 02 18:22:30 volumio volumio[1190]: Generating RSA private key, 4096 bit long modulus (2 primes) Jun 02 18:22:31 volumio systemd[1]: systemd-timedated.service: Succeeded. Jun 02 18:22:31 volumio volumio[890]: info: Getting Spotify volume Jun 02 18:22:31 volumio volumio[890]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jun 02 18:22:31 volumio volumio[890]: info: Spotify volume: 100 Jun 02 18:22:31 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:31 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:31 volumio volumio[890]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Jun 02 18:22:31 volumio volumio[890]: SPOTIFY: SPOTIFY VOLUME 100 Jun 02 18:22:31 volumio volumio[890]: SPOTIFY: VOLUMIO VOLUME 10 Jun 02 18:22:31 volumio volumio[890]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 02 18:22:31 volumio volumio[890]: info: Setting Spotify Volume from Volumio: 10 Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:32 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:32 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:32 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:32 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 02 18:22:32 volumio volumio[890]: SPOTIFY: SETTING SPOTIFY VOLUME 10 Jun 02 18:22:32 volumio volumio[890]: info: Sending Spotify command with payload to local API: /player/volume Jun 02 18:22:32 volumio go-librespot[1241]: time="2026-06-02T18:22:32+02:00" level=debug msg="update volume requested to 6553/65535" Jun 02 18:22:33 volumio go-librespot[1241]: time="2026-06-02T18:22:33+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:22:33 volumio go-librespot[1241]: time="2026-06-02T18:22:33+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:22:33 volumio volumio[890]: SPOTIFY: received: {"type":"volume","data":{"value":10,"max":100}} Jun 02 18:22:33 volumio volumio[890]: SPOTIFY: RECEIVED SPOTIFY VOLUME 10 Jun 02 18:22:34 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 02 18:22:34 volumio volumio[890]: info: Received Get System Info Jun 02 18:22:34 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 02 18:22:34 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 02 18:22:34 volumio volumio[890]: info: Discovery: Getting this device information Jun 02 18:22:34 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:34 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:34 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 02 18:22:35 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:35 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:35 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Jun 02 18:22:35 volumio volumio[1190]: ...............................++++ Jun 02 18:22:35 volumio volumio[890]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin bluetooth to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin multiroom to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin metavolumio to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin cd_controller to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 02 18:22:37 volumio volumio[890]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 02 18:22:38 volumio volumio[890]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 02 18:22:38 volumio volumio[890]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 02 18:22:38 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:38 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:38 volumio volumio[890]: info: Starting MyVolumio Remote Streaming Endpoints Jun 02 18:22:38 volumio volumio[890]: info: MyVolumio login type: Token Jun 02 18:22:38 volumio volumio[890]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 02 18:22:38 volumio volumio[890]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 02 18:22:40 volumio volumio[890]: info: Starting Streaming Service Transparent Proxy Jun 02 18:22:40 volumio volumio[890]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 02 18:22:40 volumio volumio[890]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 02 18:22:40 volumio volumio[890]: info: Streaming services startup Jun 02 18:22:40 volumio volumio[890]: info: Starting Streaming Daemon Jun 02 18:22:40 volumio sudo[1339]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 02 18:22:40 volumio sudo[1339]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:40 volumio volumio[890]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 02 18:22:40 volumio sudo[1339]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:40 volumio volumio[890]: error: Cannot start Volumio Streaming Daemon Jun 02 18:22:40 volumio volumio[890]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 02 18:22:40 volumio volumio[890]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 02 18:22:41 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:41.078+02:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.0.190:35614 error="read tcp 192.168.0.130:7331->192.168.0.190:35614: read: connection reset by peer" Jun 02 18:22:41 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:41.078+02:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.0.190:35614 Jun 02 18:22:41 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:41.078+02:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.0.190:35614 Jun 02 18:22:41 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 02 18:22:41 volumio volumio[1190]: ..............................................++++ Jun 02 18:22:41 volumio volumio[1190]: e is 65537 (0x010001) Jun 02 18:22:41 volumio volumio[1190]: writing RSA key Jun 02 18:22:42 volumio volumio[890]: STREAMING PROXY: Starting server on port 3245 Jun 02 18:22:42 volumio volumio[890]: Node JS runtime: 14 Jun 02 18:22:43 volumio volumio[890]: error: MyVolumio Custom Token format not valid, refreshing it Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=debug msg="handling transfer player command from 0a3ffcb5a5b00010d9c4775126b0e2c22a3f1009" Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=debug msg="resolved context of track" uri="spotify:station:track:7btwmzYKStDASnnx0vubga" Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:7btwmzYKStDASnnx0vubga" Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=trace msg="fetched new page from (has next: true)" uri="spotify:station:track:7btwmzYKStDASnnx0vubga" Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=trace msg="fetched new page 1 with 50 items (list: 100)" uri="spotify:station:track:7btwmzYKStDASnnx0vubga" Jun 02 18:22:44 volumio go-librespot[1241]: time="2026-06-02T18:22:44+02:00" level=debug msg="loading track (paused: false, position: 124490ms)" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=trace msg="emitting websocket event: will_play" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="selected format OGG_VORBIS_320 (ebeb8bd5a18323f4ef2e8e457a512cd4b91c2ea7)" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="requested aes key for file ebeb8bd5a18323f4ef2e8e457a512cd4b91c2ea7, gid: 13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 167" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="fetched first chunk of 24, total size is 12120849 bytes" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:45 volumio volumio[890]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:station:track:7btwmzYKStDASnnx0vubga","uri":"spotify:track:13TKpq6Zc8k0DgnQh6fxBX","play_origin":""}} Jun 02 18:22:45 volumio go-librespot[1241]: time="2026-06-02T18:22:45+02:00" level=debug msg="fetched chunk 12/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="fetched chunk 9/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=trace msg="seek to 124490ms (diff: 116ms, samples: 5490009, bytes: 5099759)" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="created new output device" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=info msg="loaded track \"Heavy Fuel\" (paused: false, position: 124490ms, duration: 297200ms, prefetched: false)" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="fetched chunk 10/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=trace msg="scheduling prefetch in 143s" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=trace msg="emitting websocket event: metadata" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=trace msg="emitting websocket event: active" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="fetched chunk 11/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:22:46 volumio go-librespot[1241]: time="2026-06-02T18:22:46+02:00" level=trace msg="emitting websocket event: playing" Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:13TKpq6Zc8k0DgnQh6fxBX","name":"Heavy Fuel","artist_names":["Dire Straits"],"album_name":"Heavy Fuel","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020d13b9c62c7e8d02a7e2feb9","position":124490,"duration":297200,"release_date":"year:1991 month:10 day:21","track_number":1,"disc_number":1}} Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: received: {"type":"active","data":null} Jun 02 18:22:46 volumio volumio[890]: info: Aligning Spotify Volume to Volumio Volume Jun 02 18:22:46 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:46 volumio volumio[890]: info: CorePlayQueue::getTrack 0 Jun 02 18:22:46 volumio volumio[890]: info: Setting Spotify Volume from Volumio: 10 Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:station:track:7btwmzYKStDASnnx0vubga","uri":"spotify:track:13TKpq6Zc8k0DgnQh6fxBX","resume":false,"play_origin":""}} Jun 02 18:22:46 volumio volumio[890]: info: Spotify is playing in volatile mode Jun 02 18:22:46 volumio volumio[890]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: UNSET VOLATILE Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: {"status":"stop","position":0,"title":"More Than a Feeling","artist":"Boston","album":"Boston (Remastered)","albumart":"http://192.168.0.101:8200/AlbumArt/14270-232149.jpg","uri":"http://192.168.0.101:8200/MediaItems/232149.flac","seek":0,"duration":285,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":10,"dbVolume":null,"disableVolumeControl":false,"mute":false,"updatedb":false,"volatile":false,"service":"upnp_browser"} Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 18:22:46 volumio volumio[890]: SPOTIFY: {"status":"play","service":"spop","title":"Heavy Fuel","artist":"Dire Straits","album":"Heavy Fuel","albumart":"https://i.scdn.co/image/ab67616d00001e020d13b9c62c7e8d02a7e2feb9","uri":"spotify:track:13TKpq6Zc8k0DgnQh6fxBX","trackType":"spotify","seek":124490,"duration":297,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 02 18:22:46 volumio volumio[890]: info: CoreCommandRouter::servicePushState Jun 02 18:22:46 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:46 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:22:46 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:46 volumio volumio[890]: info: CoreCommandRouter::volumioGetState Jun 02 18:22:46 volumio volumio[890]: info: [LastFM] Current track has sufficient metadata: title (Heavy Fuel) and artist (Dire Straits) passed on explicitly Jun 02 18:22:47 volumio volumio[890]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Jun 02 18:22:47 volumio volumio[890]: SPOTIFY: PUSH STATE SPOTIFY Jun 02 18:22:47 volumio volumio[890]: SPOTIFY: {"status":"play","service":"spop","title":"Heavy Fuel","artist":"Dire Straits","album":"Heavy Fuel","albumart":"https://i.scdn.co/image/ab67616d00001e020d13b9c62c7e8d02a7e2feb9","uri":"spotify:track:13TKpq6Zc8k0DgnQh6fxBX","trackType":"spotify","seek":124490,"duration":297,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 02 18:22:47 volumio volumio[890]: info: CoreCommandRouter::servicePushState Jun 02 18:22:47 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:47 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:47 volumio volumio[890]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Jun 02 18:22:47 volumio volumio[890]: info: Listing playlists Jun 02 18:22:47 volumio volumio[890]: info: Listing playlists Jun 02 18:22:47 volumio volumio[890]: info: MyVolumio login type: Token Jun 02 18:22:48 volumio volumio[890]: SPOTIFY: SETTING SPOTIFY VOLUME 10 Jun 02 18:22:48 volumio volumio[890]: info: Sending Spotify command with payload to local API: /player/volume Jun 02 18:22:48 volumio go-librespot[1241]: time="2026-06-02T18:22:48+02:00" level=debug msg="update volume requested to 6553/65535" Jun 02 18:22:48 volumio go-librespot[1241]: time="2026-06-02T18:22:48+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:22:48 volumio go-librespot[1241]: time="2026-06-02T18:22:48+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:22:49 volumio go-librespot[1241]: time="2026-06-02T18:22:49+02:00" level=debug msg="update volume requested to 9175/65535" Jun 02 18:22:49 volumio volumio[890]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Heavy Fuel","mbid":"0112883c-2f38-4669-b9c3-fde8889ee44b","url":"https://www.last.fm/music/Dire+Straits/_/Heavy+Fuel","duration":"284000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"256257","playcount":"1195304","artist":{"name":"Dire Straits","mbid":"614e3804-7d34-41ba-857f-811bad7c2b7a","url":"https://www.last.fm/music/Dire+Straits"},"album":{"artist":"Dire Straits","title":"On Every Street","url":"https://www.last.fm/music/Dire+Straits/On+Every+Street","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/22ed17422d49d877436aca468a7cbb3b.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/22ed17422d49d877436aca468a7cbb3b.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/22ed17422d49d877436aca468a7cbb3b.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/22ed17422d49d877436aca468a7cbb3b.png","@":{"size":"extralarge"}}]},"userplaycount":"0","userloved":"0","toptags":"","wiki":{"published":"26 Nov 2008, 18:01","summary":"In \"Heavy Fuel\", Mark Knopfler ironically extols the virtues of such conventionally frowned-upon vices as cigarettes, hamburgers, Scotch, lust, money, and violence. The phrase \"You gotta run on heavy fuel\" is from the novel Money by Martin Amis, on which Knopfler based his lyric. Read more on Last.fm.","content":"In \"Heavy Fuel\", Mark Knopfler ironically extols the virtues of such conventionally frowned-upon vices as cigarettes, hamburgers, Scotch, lust, money, and violence. The phrase \"You gotta run on heavy fuel\" is from the novel Money by Martin Amis, on which Knopfler based his lyric. Read more on Last.fm. User-contributed text is available under the Creative Commons By-SA License; additional terms may apply."}}} Jun 02 18:22:49 volumio go-librespot[1241]: time="2026-06-02T18:22:49+02:00" level=debug msg="fetched chunk 13/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:22:49 volumio volumio[890]: SPOTIFY: received: {"type":"volume","data":{"value":10,"max":100}} Jun 02 18:22:49 volumio volumio[890]: SPOTIFY: RECEIVED SPOTIFY VOLUME 10 Jun 02 18:22:49 volumio go-librespot[1241]: time="2026-06-02T18:22:49+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:22:49 volumio go-librespot[1241]: time="2026-06-02T18:22:49+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:22:50 volumio go-librespot[1241]: time="2026-06-02T18:22:50+02:00" level=debug msg="update volume requested to 11796/65535" Jun 02 18:22:50 volumio volumio[890]: SPOTIFY: received: {"type":"volume","data":{"value":14,"max":100}} Jun 02 18:22:50 volumio volumio[890]: SPOTIFY: RECEIVED SPOTIFY VOLUME 14 Jun 02 18:22:50 volumio volumio[890]: info: Setting Volumio Volume from Spotify: 14 Jun 02 18:22:50 volumio volumio[890]: info: VolumeController::SetAlsaVolume14 Jun 02 18:22:50 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:50 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:22:50 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:50 volumio volumio[890]: SPOTIFY: RECEIVED VOLUMIO VOLUME 14 Jun 02 18:22:51 volumio go-librespot[1241]: time="2026-06-02T18:22:51+02:00" level=debug msg="update volume requested to 14418/65535" Jun 02 18:22:51 volumio go-librespot[1241]: time="2026-06-02T18:22:51+02:00" level=debug msg="update volume requested to 24903/65535" Jun 02 18:22:51 volumio go-librespot[1241]: time="2026-06-02T18:22:51+02:00" level=debug msg="update volume requested to 27525/65535" Jun 02 18:22:51 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:22:51 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:22:51 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 02 18:22:51 volumio go-librespot[1241]: time="2026-06-02T18:22:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:22:51 volumio go-librespot[1241]: time="2026-06-02T18:22:51+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:22:52 volumio volumio[890]: SPOTIFY: received: {"type":"volume","data":{"value":42,"max":100}} Jun 02 18:22:52 volumio volumio[890]: SPOTIFY: RECEIVED SPOTIFY VOLUME 42 Jun 02 18:22:52 volumio volumio[890]: info: Setting Volumio Volume from Spotify: 42 Jun 02 18:22:52 volumio volumio[890]: info: VolumeController::SetAlsaVolume42 Jun 02 18:22:52 volumio volumio[890]: info: CoreStateMachine::pushState Jun 02 18:22:52 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:22:52 volumio volumio[890]: info: CoreCommandRouter::volumioPushState Jun 02 18:22:52 volumio volumio-remote-updater[641]: No test mode Jun 02 18:22:52 volumio volumio-remote-updater[641]: No alpha test mode Jun 02 18:22:52 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jun 02 18:22:52 volumio volumio[890]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 02 18:22:52 volumio volumio[890]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Jun 02 18:22:53 volumio volumio[890]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 02 18:22:53 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 02 18:22:54 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:54.148+02:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Jun 02 18:22:54 volumio volumio[890]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 02 18:22:54 volumio dbus-daemon[624]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.15" (uid=0 pid=1205 comm="/usr/bin/volumio5-onboarding ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=763 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn") Jun 02 18:22:54 volumio go-librespot[1241]: time="2026-06-02T18:22:54+02:00" level=trace msg="sent dealer ping" Jun 02 18:22:54 volumio go-librespot[1241]: time="2026-06-02T18:22:54+02:00" level=trace msg="received dealer pong" Jun 02 18:22:54 volumio volumio[890]: <--- Last few GCs ---> Jun 02 18:22:54 volumio volumio[890]: [890:0x3aff788] 54418 ms: Scavenge 162.5 (173.1) -> 162.4 (173.1) MB, 1.9 / 0.0 ms (average mu = 0.921, current mu = 0.932) allocation failure Jun 02 18:22:54 volumio volumio[890]: [890:0x3aff788] 54549 ms: Scavenge 184.2 (194.7) -> 184.1 (194.7) MB, 1.0 / 0.0 ms (average mu = 0.921, current mu = 0.932) allocation failure Jun 02 18:22:54 volumio volumio[890]: <--- JS stacktrace ---> Jun 02 18:22:54 volumio volumio[890]: FATAL ERROR: MarkCompactCollector: young object promotion failed Allocation failed - JavaScript heap out of memory Jun 02 18:22:54 volumio go-librespot[1241]: time="2026-06-02T18:22:54+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jun 02 18:22:54 volumio volumio-remote-updater[641]: [2026-06-02 18:22:54] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 02 18:22:54 volumio volumio-remote-updater[641]: [2026-06-02 18:22:54] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 02 18:22:54 volumio systemd[1]: volumio.service: Main process exited, code=killed, status=11/SEGV Jun 02 18:22:54 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:54.878+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 02 18:22:54 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:54.892+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 02 18:22:54 volumio systemd[1]: volumio.service: Failed with result 'signal'. Jun 02 18:22:54 volumio systemd[1]: Started dynamicswap service. Jun 02 18:22:55 volumio systemd[1]: dynamicswap.service: Succeeded. Jun 02 18:22:55 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jun 02 18:22:55 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Jun 02 18:22:55 volumio systemd[1]: Started dynamicswap service. Jun 02 18:22:55 volumio systemd[1]: Stopped Volumio Backend Module. Jun 02 18:22:55 volumio systemd[1]: Started Volumio Backend Module. Jun 02 18:22:55 volumio systemd[1]: dynamicswap.service: Succeeded. Jun 02 18:22:55 volumio volumio5-onboarding[1205]: time=2026-06-02T18:22:55.895+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 02 18:22:56 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:22:56 volumio volumio[1437]: info: ----- Volumio3 ---- Jun 02 18:22:56 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:22:56 volumio volumio[1437]: info: ----- System startup ---- Jun 02 18:22:56 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:22:57 volumio volumio[1437]: info: MYVOLUMIO Environment detected Jun 02 18:22:57 volumio volumio[1437]: info: Plugin folders cleanup Jun 02 18:22:57 volumio volumio[1437]: info: Scanning into folder /volumio/app/plugins/ Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category audio_interface Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category miscellanea Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category music_service Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category plugins.json Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category system_controller Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category user_interface Jun 02 18:22:57 volumio volumio[1437]: info: Scanning into folder /data/plugins/ Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category audio_interface Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category music_service Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category system_controller Jun 02 18:22:57 volumio volumio[1437]: info: Scanning category user_interface Jun 02 18:22:57 volumio volumio[1437]: info: Plugin folders cleanup completed Jun 02 18:22:57 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:22:57 volumio volumio[1437]: info: ----- Core plugins startup ---- Jun 02 18:22:57 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:22:57 volumio volumio[1437]: info: Loading plugins from folder /volumio/app/plugins/ Jun 02 18:22:57 volumio volumio[1437]: info: Adding plugin upnp to MyMusic Plugins Jun 02 18:22:57 volumio volumio[1437]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 02 18:22:57 volumio volumio[1437]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 02 18:22:57 volumio volumio[1437]: info: Loading plugins from folder /data/plugins/ Jun 02 18:22:57 volumio volumio[1437]: info: Loading plugin "system"... Jun 02 18:22:57 volumio volumio[1437]: info: Loading plugin "appearance"... Jun 02 18:22:58 volumio volumio[1437]: info: Loading plugin "network"... Jun 02 18:22:58 volumio volumio[1437]: info: Refreshing Cached IP Addresses Jun 02 18:22:58 volumio volumio[1437]: info: Loading plugin "services"... Jun 02 18:22:58 volumio volumio[1437]: info: Loading plugin "volumio5onboarding"... Jun 02 18:22:58 volumio sudo[1463]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:22:58 volumio sudo[1463]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:58 volumio sudo[1465]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:22:58 volumio sudo[1465]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:22:59 volumio sudo[1465]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:59 volumio sudo[1463]: pam_unix(sudo:session): session closed for user root Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "alsa_controller"... Jun 02 18:22:59 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "wizard"... Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "networkfs"... Jun 02 18:22:59 volumio volumio[1437]: info: Cannot mount NAS audio at system boot, trial number 1 ,retrying in 5 seconds Jun 02 18:22:59 volumio volumio[1437]: info: Starting Udev Watcher for removable devices Jun 02 18:22:59 volumio volumio[1437]: info: Ignoring mount for partition: boot Jun 02 18:22:59 volumio volumio[1437]: info: Ignoring mount for partition: volumio Jun 02 18:22:59 volumio volumio[1437]: info: Ignoring mount for partition: volumio_data Jun 02 18:22:59 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "volumio_command_line_client"... Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "upnp"... Jun 02 18:22:59 volumio volumio[1437]: info: [1780417379218] Starting Upmpd Daemon Jun 02 18:22:59 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "my_music"... Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "mpd"... Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "upnp_browser"... Jun 02 18:22:59 volumio volumio-remote-updater[641]: [2026-06-02 18:22:59] [connect] Successful connection Jun 02 18:22:59 volumio volumio[1437]: info: Starting UPNP Browser Jun 02 18:22:59 volumio volumio[1437]: info: Loading plugin "alarm-clock"... Jun 02 18:23:00 volumio volumio[1437]: info: Plugin airplay_emulation is not enabled Jun 02 18:23:00 volumio volumio[1437]: info: Loading plugin "last_100"... Jun 02 18:23:00 volumio volumio[1437]: info: Loading plugin "webradio"... Jun 02 18:23:00 volumio volumio[1437]: info: Loading plugin "i2s_dacs"... Jun 02 18:23:00 volumio volumio[1437]: info: Loading plugin "volumiodiscovery"... Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** For more information see Jun 02 18:23:00 volumio node[1437]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:00 volumio volumio[1437]: *** WARNING *** For more information see Jun 02 18:23:00 volumio node[1437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:00 volumio node[1437]: *** WARNING *** For more information see Jun 02 18:23:00 volumio node[1437]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:00 volumio node[1437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:00 volumio node[1437]: *** WARNING *** For more information see Jun 02 18:23:00 volumio volumio[1437]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 02 18:23:00 volumio volumio[1437]: info: Discovery: Started advertising with name: Volumio Jun 02 18:23:00 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:23:00 volumio volumio[1437]: info: Loading plugin "spop"... Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "outputs"... Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "albumart"... Jun 02 18:23:01 volumio volumio[1437]: info: Plugin example_plugin is not enabled Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "inputs"... Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "updater_comm"... Jun 02 18:23:01 volumio go-librespot[1241]: time="2026-06-02T18:23:01+02:00" level=debug msg="fetched chunk 14/23, size: 524288" uri="spotify:track:13TKpq6Zc8k0DgnQh6fxBX" Jun 02 18:23:01 volumio volumio[1437]: info: Plugin mpdemulation is not enabled Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "rest_api"... Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "websocket"... Jun 02 18:23:01 volumio volumio[1437]: info: Starting Socket.io Server version 2.3.0 Jun 02 18:23:01 volumio volumio[1437]: info: Plugin fusiondsp is not enabled Jun 02 18:23:01 volumio volumio[1437]: info: Loading plugin "backup_restore"... Jun 02 18:23:01 volumio volumio[1437]: Forking 3 albumart workers Jun 02 18:23:02 volumio volumio[1437]: info: Applying required configuration parameters for plugin backup_restore Jun 02 18:23:02 volumio volumio[1437]: info: Loading plugin "Systeminfo"... Jun 02 18:23:02 volumio volumio[1437]: info: Loading plugin "lastfm"... Jun 02 18:23:02 volumio volumio[1437]: Starting albumart workers Jun 02 18:23:02 volumio volumio[1437]: Starting albumart workers Jun 02 18:23:03 volumio volumio[1437]: Starting albumart workers Jun 02 18:23:03 volumio volumio[1437]: info: Loading i18n strings for locale de Jun 02 18:23:03 volumio volumio[1437]: Updating browse sources language Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::initPlayerControls Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:03 volumio volumio[1437]: Express server listening on port 3000 Jun 02 18:23:03 volumio volumio[1437]: [Metrics] WebUI: 7s 280.63ms Jun 02 18:23:03 volumio volumio[1437]: info: CoreStateMachine::resetVolumioState Jun 02 18:23:03 volumio volumio[1437]: info: CoreStateMachine::getcurrentVolume Jun 02 18:23:03 volumio volumio[1437]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:23:03 volumio ntpd[783]: Soliciting pool server 217.175.198.239 Jun 02 18:23:03 volumio volumio[1437]: info: Volumio Network Manager: Network status updated: 1 Jun 02 18:23:03 volumio volumio[1437]: 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: 1 Jun 02 18:23:03 volumio volumio-remote-updater[641]: [2026-06-02 18:23:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1780417379 101 Jun 02 18:23:03 volumio volumio[1437]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Jun 02 18:23:03 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:04 volumio volumio[1437]: info: Reloading queue from file Jun 02 18:23:04 volumio volumio[1437]: 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: 3 Jun 02 18:23:04 volumio volumio[1437]: info: VolumeController:: Volume=41 Mute =false Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::pushState Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::updateTrackBlock Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrackBlock Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::setRepeat false single undefined Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::pushState Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::setRandom null Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::pushState Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:04 volumio volumio[1437]: info: Setting Device type: Raspberry PI Jun 02 18:23:04 volumio volumio[1437]: info: Completed loading Core Plugins Jun 02 18:23:04 volumio volumio[1437]: info: Preparing to generate the ALSA configuration file Jun 02 18:23:04 volumio volumio[1437]: 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: 3 Jun 02 18:23:04 volumio volumio[1437]: info: Cannot mount NAS audio at system boot, trial number 2 ,retrying in 5 seconds Jun 02 18:23:04 volumio volumio[1437]: 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: 3 Jun 02 18:23:04 volumio volumio[1437]: info: Asound.conf file unchanged, so no further update is needed Jun 02 18:23:04 volumio volumio[1437]: info: Output device has changed, restarting MPD Jun 02 18:23:04 volumio sudo[1555]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:23:04 volumio volumio[1437]: info: ___________ START PLUGINS ___________ Jun 02 18:23:04 volumio sudo[1555]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio sudo[1555]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:04 volumio sudo[1557]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:23:04 volumio sudo[1557]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio volumio[1437]: info: ControllerMpd::onStart: Initializing MPD Jun 02 18:23:04 volumio volumio[1437]: info: Creating MPD Configuration file Jun 02 18:23:04 volumio sudo[1561]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 02 18:23:04 volumio sudo[1561]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio systemd[1]: Stopping Music Player Daemon... Jun 02 18:23:04 volumio sudo[1564]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:23:04 volumio sudo[1564]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:04 volumio sudo[1564]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:04 volumio volumio[1437]: info: [1780417384408] CoreMusicLibrary::Adding element Medienserver Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:04 volumio sudo[1566]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:23:04 volumio sudo[1566]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio sudo[1561]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:04 volumio volumio[1437]: info: UPNP Browser: Client initialized successfully Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:04 volumio volumio[1437]: info: [1780417384469] CoreMusicLibrary::Adding element Last_100 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:04 volumio volumio[1437]: info: [1780417384473] CoreMusicLibrary::Adding element Webradio Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:23:04 volumio volumio[1437]: info: Initializing BBC Radios Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:04 volumio volumio[1437]: info: Creating Spotify config file Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:04 volumio volumio[1437]: info: [1780417384649] CoreMusicLibrary::Adding element LastFM Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:04 volumio volumio[1437]: Cannot find translation for source LastFM Jun 02 18:23:04 volumio volumio[1437]: info: [LastFM] scrobbler initiated! Jun 02 18:23:04 volumio volumio[1437]: info: [LastFM] extended logging: false Jun 02 18:23:04 volumio volumio[1437]: info: [LastFM] try scrobble stream/radio plays: true Jun 02 18:23:04 volumio volumio[1437]: info: [LastFM] Left init routine Jun 02 18:23:04 volumio volumio[1437]: info: [LastFM] Socket already connected: true Jun 02 18:23:04 volumio volumio[1437]: info: Volumio Calling Home Jun 02 18:23:04 volumio ntpd[783]: Soliciting pool server 152.53.184.240 Jun 02 18:23:04 volumio systemd[1]: mpd.service: Succeeded. Jun 02 18:23:04 volumio systemd[1]: Stopped Music Player Daemon. Jun 02 18:23:04 volumio volumio[1437]: info: Discovery: adding 198b4bbd-3d07-43db-9a28-8aeacee0c349 Jun 02 18:23:04 volumio volumio[1437]: info: Discovery: Found device Volumio Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:04 volumio systemd[1]: Starting Music Player Daemon... Jun 02 18:23:04 volumio volumio[1437]: info: VolumeController:: Volume=41 Mute =false Jun 02 18:23:04 volumio volumio[1437]: info: CoreStateMachine::pushState Jun 02 18:23:04 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:04 volumio volumio[1437]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:04 volumio volumio[1437]: 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: 3 Jun 02 18:23:04 volumio volumio[1437]: info: MPD Permissions set Jun 02 18:23:04 volumio volumio[1437]: info: MPD Permissions set Jun 02 18:23:04 volumio volumio[1437]: info: Spotify config file written Jun 02 18:23:04 volumio sudo[1584]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 18:23:04 volumio sudo[1581]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 18:23:04 volumio sudo[1581]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio sudo[1584]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:04 volumio sudo[1581]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:05 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jun 02 18:23:05 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Jun 02 18:23:05 volumio systemd[1]: Stopping go-librespot Daemon... Jun 02 18:23:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 02 18:23:05 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 02 18:23:05 volumio systemd[1]: Stopped go-librespot Daemon. Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio systemd[1]: Started go-librespot Daemon. Jun 02 18:23:05 volumio sudo[1584]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:05 volumio go-librespot[1588]: go-librespot daemon starting... Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio go-librespot[1588]: time="2026-06-02T18:23:05+02:00" level=info msg="running go-librespot 0.4.0" Jun 02 18:23:05 volumio go-librespot[1588]: time="2026-06-02T18:23:05+02:00" level=debug msg="app state loaded" Jun 02 18:23:05 volumio go-librespot[1588]: time="2026-06-02T18:23:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:05 volumio volumio[1437]: info: No need to fix Spotify hosts Jun 02 18:23:05 volumio volumio[1437]: info: Volumio called home Jun 02 18:23:05 volumio volumio[1437]: info: [LastFM] finished init: Authenticated successfully! Jun 02 18:23:05 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:05 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:05 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 4 Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:05 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:05 volumio volumio[1437]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:23:05 volumio volumio[1437]: SPOTIFY: BQBOKFFD77peUxmQUId_5vfvdYOJRPyC9GQin0dv_DDIVuf2dL7zweFLiyebkRiIQa23ZHIxcK8mojFqmKv4325bz_9PmILxtHhfWe9doSfLLjrHgLAZgYywQ692NixvrF3_60gfF0A8mSqcyjBg70ninzO3KdiuTPI3_12TbnjDwq7A2b4l1-Nn7csc_YSaAoTHdfaKKDTn_DPqSAUjRRytrP28xDwDd4GStNGWHBLWN43zg9QvsjbbYWXTAfwKvb7F4mjdeZZ9gYPnUeW9Yk78a2TuEnkmMA Jun 02 18:23:05 volumio volumio[1437]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:23:05 volumio volumio[1437]: info: New Spotify access token = BQBOKFFD77peUxmQUId_5vfvdYOJRPyC9GQin0dv_DDIVuf2dL7zweFLiyebkRiIQa23ZHIxcK8mojFqmKv4325bz_9PmILxtHhfWe9doSfLLjrHgLAZgYywQ692NixvrF3_60gfF0A8mSqcyjBg70ninzO3KdiuTPI3_12TbnjDwq7A2b4l1-Nn7csc_YSaAoTHdfaKKDTn_DPqSAUjRRytrP28xDwDd4GStNGWHBLWN43zg9QvsjbbYWXTAfwKvb7F4mjdeZZ9gYPnUeW9Yk78a2TuEnkmMA Jun 02 18:23:05 volumio volumio[1437]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 02 18:23:05 volumio volumio[1437]: info: Listing playlists Jun 02 18:23:05 volumio volumio[1437]: info: Listing playlists Jun 02 18:23:05 volumio ntpd[783]: Soliciting pool server 162.159.200.123 Jun 02 18:23:05 volumio ntpd[783]: Soliciting pool server 152.53.15.127 Jun 02 18:23:05 volumio ntpd[783]: Soliciting pool server 152.53.100.131 Jun 02 18:23:05 volumio volumio[1437]: SPOTIFY: User informations: {"account_id":"Rf8p5ogBAa","country":"AT","display_name":"288 GTO","email":"288gto@gmx.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/288_gto"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/288_gto","id":"288_gto","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85467fa7ce35d304790fe5f608","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82467fa7ce35d304790fe5f608","width":64}],"product":"premium","type":"user","uri":"spotify:user:288_gto"} Jun 02 18:23:05 volumio volumio[1437]: info: Spotify Successfully logged in Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:05 volumio volumio[1437]: info: [1780417385844] CoreMusicLibrary::Adding element Spotify Jun 02 18:23:05 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:05 volumio volumio[1437]: Cannot find translation for source LastFM Jun 02 18:23:05 volumio volumio[1437]: Cannot find translation for source Spotify Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" 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]" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" 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]" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" 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]" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=info msg="zeroconf server listening on port 44927" Jun 02 18:23:06 volumio mpd[1587]: Jun 02 18:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=debug msg="obtained new client token: AACvZn0zIbBSysUs8hRJPUte9kztHwI2m6rwu6QPHhmaVAVl/1YiXKXRpDAO8aPT9TRd3zXPD3qqMbVuvnbQFzLINU3yM4heYun7YwNyrmcpsuPPjLVzZI/zJHcPLbtm+CjJUvjoQE6ayc/7D4pkreEykU+aJZIIHWlghO+GRTzC4kOcdpYqyMKs2xv8+QtubHbmuIXO1lSFDtc0u2UrXQKCJgWCAGadA14EVFUYfORPi0LJcJH5" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 02 18:23:06 volumio ntpd[783]: Soliciting pool server 37.252.189.117 Jun 02 18:23:06 volumio ntpd[783]: Soliciting pool server 78.41.116.149 Jun 02 18:23:06 volumio ntpd[783]: Soliciting pool server 152.53.119.76 Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=debug msg="completed keyexchange" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=debug msg="completed challenge" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=info msg="authenticated AP" username="28***to" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=info msg="authenticated Login5" username="28***to" Jun 02 18:23:06 volumio go-librespot[1588]: time="2026-06-02T18:23:06+02:00" level=debug msg="initializing zeroconf session" username="28***to" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="dealer connection opened" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=trace msg="starting accesspoint recv loop" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=trace msg="starting dealer recv loop" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=trace msg="received accesspoint ping" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="received connection id: MDBlYmQ0ZTQtMDY0...M0UyNTkxQkEwRg==" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=trace msg="received accesspoint pong ack" Jun 02 18:23:07 volumio go-librespot[1588]: time="2026-06-02T18:23:07+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 02 18:23:07 volumio ntpd[783]: Soliciting pool server 46.102.157.67 Jun 02 18:23:07 volumio ntpd[783]: Soliciting pool server 2a0a:4cc0:c0:1264:c4b0:eaff:fe65:e4bf Jun 02 18:23:07 volumio ntpd[783]: Soliciting pool server 152.53.132.244 Jun 02 18:23:08 volumio volumio[1437]: info: go-librespot daemon successfully initialized Jun 02 18:23:08 volumio systemd[1]: Started Music Player Daemon. Jun 02 18:23:08 volumio sudo[1566]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:08 volumio sudo[1557]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:08 volumio volumio[1437]: info: Completed starting Core Plugins Jun 02 18:23:08 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:23:08 volumio volumio[1437]: info: ----- MyVolumio plugins startup ---- Jun 02 18:23:08 volumio volumio[1437]: info: ------------------------------------------- Jun 02 18:23:08 volumio volumio[1437]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 02 18:23:08 volumio volumio[1437]: error: MPD error: The expression evaluated to a falsy value: Jun 02 18:23:08 volumio volumio[1437]: assert.ok(self.idling) Jun 02 18:23:08 volumio volumio[1437]: error: The expression evaluated to a falsy value: Jun 02 18:23:08 volumio volumio[1437]: assert.ok(self.idling) Jun 02 18:23:08 volumio volumio[1437]: info: MPD running with PID1587 Jun 02 18:23:08 volumio volumio[1437]: ,establishing connection Jun 02 18:23:08 volumio volumio[1437]: error: MPD error: The expression evaluated to a falsy value: Jun 02 18:23:08 volumio volumio[1437]: assert.ok(self.idling) Jun 02 18:23:08 volumio volumio[1437]: error: The expression evaluated to a falsy value: Jun 02 18:23:08 volumio volumio[1437]: assert.ok(self.idling) Jun 02 18:23:08 volumio volumio[1437]: error: updateQueue error: null Jun 02 18:23:09 volumio volumio[1437]: info: Cannot mount NAS audio at system boot, trial number 3 ,retrying in 5 seconds Jun 02 18:23:09 volumio sudo[1625]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:23:09 volumio sudo[1625]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:09 volumio sudo[1625]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:09 volumio sudo[1627]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:23:09 volumio sudo[1627]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:09 volumio sudo[1627]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:09 volumio sudo[1631]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 02 18:23:09 volumio sudo[1631]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:09 volumio sudo[1631]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:09 volumio volumio[1437]: info: Upmpdcli Daemon Started Jun 02 18:23:11 volumio volumio[1437]: info: Initializing connection to go-librespot Websocket Jun 02 18:23:11 volumio go-librespot[1588]: time="2026-06-02T18:23:11+02:00" level=debug msg="new websocket client" Jun 02 18:23:11 volumio volumio[1437]: info: Connection to go-librespot Websocket established Jun 02 18:23:11 volumio go-librespot[1588]: time="2026-06-02T18:23:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 305" Jun 02 18:23:11 volumio go-librespot[1588]: time="2026-06-02T18:23:11+02:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:list:play-history:v1/resume-point-revision/0f26a82a-0f0a-4454-a506-39c1ad6327a5" Jun 02 18:23:11 volumio go-librespot[1588]: time="2026-06-02T18:23:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 397" Jun 02 18:23:11 volumio go-librespot[1588]: time="2026-06-02T18:23:11+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 02 18:23:13 volumio ntpd[783]: receive: Unexpected origin timestamp 0xedc981f0.b72fbbd0 does not match aorg 0000000000.00000000 from server@152.53.132.244 xmt 0xedc981f1.5b15c656 Jun 02 18:23:13 volumio ntpd[783]: receive: Unexpected origin timestamp 0xedc981f0.b737e3c4 does not match aorg 0000000000.00000000 from server@152.53.119.76 xmt 0xedc981f1.5c1cbe0e Jun 02 18:23:13 volumio ntpd[783]: receive: Unexpected origin timestamp 0xedc981f0.b73ef785 does not match aorg 0000000000.00000000 from server@152.53.184.240 xmt 0xedc981f1.5c52589c Jun 02 18:23:13 volumio ntpd[783]: receive: Unexpected origin timestamp 0xedc981f0.b73a95e5 does not match aorg 0000000000.00000000 from server@152.53.15.127 xmt 0xedc981f1.5cdc3930 Jun 02 18:23:14 volumio volumio[1437]: info: Cannot mount NAS audio at system boot, trial number 4 ,retrying in 5 seconds Jun 02 18:23:15 volumio volumio[1437]: info: Getting Spotify volume Jun 02 18:23:15 volumio volumio[1437]: info: Spotify volume: 100 Jun 02 18:23:15 volumio volumio[1437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jun 02 18:23:15 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:15 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:15 volumio volumio[1437]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Jun 02 18:23:15 volumio volumio[1437]: SPOTIFY: SPOTIFY VOLUME 100 Jun 02 18:23:15 volumio volumio[1437]: SPOTIFY: VOLUMIO VOLUME 41 Jun 02 18:23:15 volumio volumio[1437]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 02 18:23:15 volumio volumio[1437]: info: Setting Spotify Volume from Volumio: 41 Jun 02 18:23:15 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:15 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:16 volumio volumio[1437]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 02 18:23:16 volumio volumio[1437]: SPOTIFY: SETTING SPOTIFY VOLUME 41 Jun 02 18:23:16 volumio volumio[1437]: info: Sending Spotify command with payload to local API: /player/volume Jun 02 18:23:16 volumio go-librespot[1588]: time="2026-06-02T18:23:16+02:00" level=debug msg="update volume requested to 26869/65535" Jun 02 18:23:17 volumio go-librespot[1588]: time="2026-06-02T18:23:17+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:17 volumio go-librespot[1588]: time="2026-06-02T18:23:17+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:17 volumio volumio[1437]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Jun 02 18:23:17 volumio volumio[1437]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin bluetooth to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin multiroom to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin metavolumio to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin cd_controller to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 02 18:23:18 volumio volumio[1437]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 02 18:23:19 volumio volumio[1437]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 02 18:23:19 volumio volumio[1437]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 02 18:23:19 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:19 volumio volumio[1437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:19 volumio volumio[1437]: info: Starting MyVolumio Remote Streaming Endpoints Jun 02 18:23:19 volumio volumio[1437]: info: MyVolumio login type: Token Jun 02 18:23:19 volumio volumio[1437]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 02 18:23:19 volumio volumio[1437]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 02 18:23:20 volumio volumio[1437]: info: Starting Streaming Service Transparent Proxy Jun 02 18:23:20 volumio volumio[1437]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 02 18:23:20 volumio volumio[1437]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 02 18:23:20 volumio volumio[1437]: info: Streaming services startup Jun 02 18:23:20 volumio volumio[1437]: info: Starting Streaming Daemon Jun 02 18:23:20 volumio sudo[1654]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 02 18:23:20 volumio sudo[1654]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:20 volumio sudo[1654]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:20 volumio volumio[1437]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 02 18:23:20 volumio volumio[1437]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Jun 02 18:23:21 volumio volumio[1437]: error: Cannot start Volumio Streaming Daemon Jun 02 18:23:21 volumio volumio[1437]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 02 18:23:21 volumio volumio[1437]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 02 18:23:22 volumio volumio[1437]: STREAMING PROXY: Starting server on port 3245 Jun 02 18:23:22 volumio volumio[1437]: Node JS runtime: 14 Jun 02 18:23:25 volumio volumio[1437]: error: MyVolumio Custom Token format not valid, refreshing it Jun 02 18:23:26 volumio volumio[1437]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:26 volumio volumio[1437]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:27 volumio volumio[1437]: info: Listing playlists Jun 02 18:23:27 volumio volumio[1437]: info: Listing playlists Jun 02 18:23:29 volumio volumio[1437]: info: MyVolumio login type: Token Jun 02 18:23:34 volumio volumio[1437]: <--- Last few GCs ---> Jun 02 18:23:34 volumio volumio[1437]: [1437:0x41bf788] 37973 ms: Scavenge 165.6 (176.2) -> 165.6 (176.2) MB, 1.2 / 0.0 ms (average mu = 0.927, current mu = 0.946) allocation failure Jun 02 18:23:34 volumio volumio[1437]: [1437:0x41bf788] 38095 ms: Scavenge 187.9 (198.5) -> 187.8 (198.5) MB, 0.9 / 0.0 ms (average mu = 0.927, current mu = 0.946) allocation failure Jun 02 18:23:34 volumio volumio[1437]: <--- JS stacktrace ---> Jun 02 18:23:34 volumio volumio[1437]: FATAL ERROR: MarkCompactCollector: young object promotion failed Allocation failed - JavaScript heap out of memory Jun 02 18:23:34 volumio volumio-remote-updater[641]: [2026-06-02 18:23:34] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 02 18:23:34 volumio volumio-remote-updater[641]: [2026-06-02 18:23:34] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 02 18:23:34 volumio systemd[1]: volumio.service: Main process exited, code=killed, status=11/SEGV Jun 02 18:23:34 volumio volumio5-onboarding[1205]: time=2026-06-02T18:23:34.103+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 02 18:23:34 volumio go-librespot[1588]: time="2026-06-02T18:23:34+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jun 02 18:23:34 volumio volumio5-onboarding[1205]: time=2026-06-02T18:23:34.112+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 02 18:23:34 volumio systemd[1]: volumio.service: Failed with result 'signal'. Jun 02 18:23:34 volumio systemd[1]: Started dynamicswap service. Jun 02 18:23:34 volumio systemd[1]: dynamicswap.service: Succeeded. Jun 02 18:23:34 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jun 02 18:23:34 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Jun 02 18:23:34 volumio systemd[1]: Stopped Volumio Backend Module. Jun 02 18:23:34 volumio systemd[1]: Started Volumio Backend Module. Jun 02 18:23:34 volumio systemd[1]: Started dynamicswap service. Jun 02 18:23:34 volumio systemd[1]: dynamicswap.service: Succeeded. Jun 02 18:23:35 volumio volumio5-onboarding[1205]: time=2026-06-02T18:23:35.115+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=debug msg="handling transfer player command from 0a3ffcb5a5b00010d9c4775126b0e2c22a3f1009" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=debug msg="resolved context of track" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=debug msg="shuffled context with seed 9014264353087956864 (len: 1, keep: -1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=debug msg="loading track (paused: true, position: 19853ms)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:35 volumio go-librespot[1588]: time="2026-06-02T18:23:35+02:00" level=trace msg="emitting websocket event: will_play" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 310" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (1b14835563c9295a7876aec8ec33a4d89a3b91e1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="requested aes key for file 1b14835563c9295a7876aec8ec33a4d89a3b91e1, gid: 7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:36 volumio volumio[1681]: info: ----- Volumio3 ---- Jun 02 18:23:36 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:36 volumio volumio[1681]: info: ----- System startup ---- Jun 02 18:23:36 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="fetched first chunk of 27, total size is 14072484 bytes" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=trace msg="seek to 19853ms (diff: 196ms, samples: 875517, bytes: 757678)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="created new output device" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=info msg="loaded track \"Industrial Disease\" (paused: true, position: 19853ms, duration: 348440ms, prefetched: false)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=trace msg="emitting websocket event: metadata" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=trace msg="emitting websocket event: active" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=trace msg="emitting websocket event: paused" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="update volume requested to 24248/65535" Jun 02 18:23:36 volumio go-librespot[1588]: time="2026-06-02T18:23:36+02:00" level=debug msg="fetched chunk 4/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:36 volumio volumio[1681]: info: MYVOLUMIO Environment detected Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:37 volumio volumio[1681]: info: Plugin folders cleanup Jun 02 18:23:37 volumio volumio[1681]: info: Scanning into folder /volumio/app/plugins/ Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category audio_interface Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category miscellanea Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category music_service Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category plugins.json Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category system_controller Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category user_interface Jun 02 18:23:37 volumio volumio[1681]: info: Scanning into folder /data/plugins/ Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category audio_interface Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category music_service Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category system_controller Jun 02 18:23:37 volumio volumio[1681]: info: Scanning category user_interface Jun 02 18:23:37 volumio volumio[1681]: info: Plugin folders cleanup completed Jun 02 18:23:37 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:37 volumio volumio[1681]: info: ----- Core plugins startup ---- Jun 02 18:23:37 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:37 volumio volumio[1681]: info: Loading plugins from folder /volumio/app/plugins/ Jun 02 18:23:37 volumio volumio[1681]: info: Adding plugin upnp to MyMusic Plugins Jun 02 18:23:37 volumio volumio[1681]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 02 18:23:37 volumio volumio[1681]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 02 18:23:37 volumio volumio[1681]: info: Loading plugins from folder /data/plugins/ Jun 02 18:23:37 volumio volumio[1681]: info: Loading plugin "system"... Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=debug msg="update volume requested to 21627/65535" Jun 02 18:23:37 volumio volumio[1681]: info: Loading plugin "appearance"... Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=debug msg="update volume requested to 13762/65535" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=trace msg="sent dealer ping" Jun 02 18:23:37 volumio go-librespot[1588]: time="2026-06-02T18:23:37+02:00" level=trace msg="received dealer pong" Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "network"... Jun 02 18:23:38 volumio volumio[1681]: info: Refreshing Cached IP Addresses Jun 02 18:23:38 volumio sudo[1708]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:23:38 volumio sudo[1708]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:38 volumio sudo[1708]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:38 volumio sudo[1710]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:23:38 volumio sudo[1710]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "services"... Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "volumio5onboarding"... Jun 02 18:23:38 volumio sudo[1710]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "alsa_controller"... Jun 02 18:23:38 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "wizard"... Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "networkfs"... Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="handling resume player command from 0a3ffcb5a5b00010d9c4775126b0e2c22a3f1009" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=trace msg="seek to 19853ms (diff: 196ms, samples: 875517, bytes: 757678)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:38 volumio volumio[1681]: info: Cannot mount NAS audio at system boot, trial number 1 ,retrying in 5 seconds Jun 02 18:23:38 volumio volumio[1681]: info: Starting Udev Watcher for removable devices Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="resume track at 19657ms" Jun 02 18:23:38 volumio volumio[1681]: info: Ignoring mount for partition: boot Jun 02 18:23:38 volumio volumio[1681]: info: Ignoring mount for partition: volumio Jun 02 18:23:38 volumio volumio[1681]: info: Ignoring mount for partition: volumio_data Jun 02 18:23:38 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "volumio_command_line_client"... Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "upnp"... Jun 02 18:23:38 volumio volumio[1681]: info: [1780417418395] Starting Upmpd Daemon Jun 02 18:23:38 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "my_music"... Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "mpd"... Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=trace msg="scheduling prefetch in 299s" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:38 volumio go-librespot[1588]: time="2026-06-02T18:23:38+02:00" level=trace msg="emitting websocket event: playing" Jun 02 18:23:38 volumio volumio[1681]: info: Loading plugin "upnp_browser"... Jun 02 18:23:39 volumio volumio[1681]: info: Starting UPNP Browser Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "alarm-clock"... Jun 02 18:23:39 volumio volumio-remote-updater[641]: [2026-06-02 18:23:39] [connect] Successful connection Jun 02 18:23:39 volumio volumio[1681]: info: Plugin airplay_emulation is not enabled Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "last_100"... Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "webradio"... Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "i2s_dacs"... Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "volumiodiscovery"... Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** For more information see Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:39 volumio node[1681]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:39 volumio volumio[1681]: *** WARNING *** For more information see Jun 02 18:23:39 volumio node[1681]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:39 volumio node[1681]: *** WARNING *** For more information see Jun 02 18:23:39 volumio node[1681]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 02 18:23:39 volumio node[1681]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 02 18:23:39 volumio node[1681]: *** WARNING *** For more information see Jun 02 18:23:39 volumio volumio[1681]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 02 18:23:39 volumio volumio[1681]: info: Discovery: Started advertising with name: Volumio Jun 02 18:23:39 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 02 18:23:39 volumio volumio[1681]: info: Loading plugin "spop"... Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=debug msg="handling seek_to player command from 0a3ffcb5a5b00010d9c4775126b0e2c22a3f1009" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=debug msg="seek track to 0ms" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=trace msg="scheduling prefetch in 318s" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=trace msg="emitting websocket event: seek" Jun 02 18:23:39 volumio go-librespot[1588]: time="2026-06-02T18:23:39+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "outputs"... Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "albumart"... Jun 02 18:23:40 volumio volumio[1681]: info: Plugin example_plugin is not enabled Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "inputs"... Jun 02 18:23:40 volumio go-librespot[1588]: time="2026-06-02T18:23:40+02:00" level=debug msg="update volume requested to 16384/65535" Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "updater_comm"... Jun 02 18:23:40 volumio go-librespot[1588]: time="2026-06-02T18:23:40+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:40 volumio go-librespot[1588]: time="2026-06-02T18:23:40+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:40 volumio volumio[1681]: info: Plugin mpdemulation is not enabled Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "rest_api"... Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "websocket"... Jun 02 18:23:40 volumio volumio[1681]: info: Starting Socket.io Server version 2.3.0 Jun 02 18:23:40 volumio volumio[1681]: info: Plugin fusiondsp is not enabled Jun 02 18:23:40 volumio volumio[1681]: info: Loading plugin "backup_restore"... Jun 02 18:23:40 volumio go-librespot[1588]: time="2026-06-02T18:23:40+02:00" level=debug msg="update volume requested to 19005/65535" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:41 volumio volumio[1681]: Forking 3 albumart workers Jun 02 18:23:41 volumio volumio[1681]: info: Applying required configuration parameters for plugin backup_restore Jun 02 18:23:41 volumio volumio[1681]: info: Loading plugin "Systeminfo"... Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=debug msg="update volume requested to 37355/65535" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:41 volumio volumio[1681]: info: Loading plugin "lastfm"... Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=debug msg="update volume requested to 42598/65535" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:41 volumio go-librespot[1588]: time="2026-06-02T18:23:41+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="update volume requested to 45219/65535" Jun 02 18:23:42 volumio volumio[1681]: Starting albumart workers Jun 02 18:23:42 volumio volumio[1681]: Starting albumart workers Jun 02 18:23:42 volumio volumio[1681]: Starting albumart workers Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="update volume requested to 47841/65535" Jun 02 18:23:42 volumio volumio[1681]: info: Loading i18n strings for locale de Jun 02 18:23:42 volumio volumio[1681]: Updating browse sources language Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="update volume requested to 55705/65535" Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::initPlayerControls Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 18:23:42 volumio go-librespot[1588]: time="2026-06-02T18:23:42+02:00" level=trace msg="emitting websocket event: volume" Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:42 volumio volumio[1681]: Express server listening on port 3000 Jun 02 18:23:42 volumio volumio[1681]: [Metrics] WebUI: 7s 247.53ms Jun 02 18:23:42 volumio volumio[1681]: info: CoreStateMachine::resetVolumioState Jun 02 18:23:42 volumio volumio[1681]: info: CoreStateMachine::getcurrentVolume Jun 02 18:23:42 volumio volumio[1681]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:23:42 volumio volumio[1681]: info: Volumio Network Manager: Network status updated: 1 Jun 02 18:23:43 volumio volumio[1681]: 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: 1 Jun 02 18:23:43 volumio volumio-remote-updater[641]: [2026-06-02 18:23:43] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1780417419 101 Jun 02 18:23:43 volumio volumio[1681]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:43 volumio volumio[1681]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:43 volumio volumio[1681]: info: Reloading queue from file Jun 02 18:23:43 volumio volumio[1681]: 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: 3 Jun 02 18:23:43 volumio volumio[1681]: info: VolumeController:: Volume=41 Mute =false Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::pushState Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::updateTrackBlock Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrackBlock Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioRetrievevolume Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::setRepeat false single undefined Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::pushState Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::setRandom null Jun 02 18:23:43 volumio volumio[1681]: info: CoreStateMachine::pushState Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:43 volumio volumio[1681]: info: Setting Device type: Raspberry PI Jun 02 18:23:43 volumio volumio[1681]: info: Listing playlists Jun 02 18:23:43 volumio volumio[1681]: info: Listing playlists Jun 02 18:23:43 volumio volumio[1681]: info: Completed loading Core Plugins Jun 02 18:23:43 volumio volumio[1681]: info: Preparing to generate the ALSA configuration file Jun 02 18:23:43 volumio volumio[1681]: 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: 3 Jun 02 18:23:43 volumio volumio[1681]: info: Cannot mount NAS audio at system boot, trial number 2 ,retrying in 5 seconds Jun 02 18:23:43 volumio volumio[1681]: 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: 3 Jun 02 18:23:43 volumio volumio[1681]: info: Asound.conf file unchanged, so no further update is needed Jun 02 18:23:43 volumio volumio[1681]: info: Output device has changed, restarting MPD Jun 02 18:23:43 volumio sudo[1799]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:23:43 volumio sudo[1799]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio volumio[1681]: info: ___________ START PLUGINS ___________ Jun 02 18:23:43 volumio sudo[1799]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:43 volumio sudo[1801]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:23:43 volumio sudo[1801]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio volumio[1681]: info: ControllerMpd::onStart: Initializing MPD Jun 02 18:23:43 volumio volumio[1681]: info: Creating MPD Configuration file Jun 02 18:23:43 volumio systemd[1]: Stopping Music Player Daemon... Jun 02 18:23:43 volumio sudo[1805]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 02 18:23:43 volumio sudo[1805]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio sudo[1807]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 02 18:23:43 volumio sudo[1807]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 02 18:23:43 volumio sudo[1807]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:43 volumio volumio[1681]: info: [1780417423577] CoreMusicLibrary::Adding element Medienserver Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:43 volumio sudo[1805]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:43 volumio sudo[1810]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 02 18:23:43 volumio sudo[1810]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio volumio[1681]: info: UPNP Browser: Client initialized successfully Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:43 volumio volumio[1681]: info: [1780417423626] CoreMusicLibrary::Adding element Last_100 Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:43 volumio volumio[1681]: info: [1780417423630] CoreMusicLibrary::Adding element Webradio Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:23:43 volumio volumio[1681]: info: Initializing BBC Radios Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:43 volumio volumio[1681]: info: Creating Spotify config file Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:43 volumio systemd[1]: mpd.service: Succeeded. Jun 02 18:23:43 volumio systemd[1]: Stopped Music Player Daemon. Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:43 volumio volumio[1681]: info: [1780417423813] CoreMusicLibrary::Adding element LastFM Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:43 volumio volumio[1681]: Cannot find translation for source LastFM Jun 02 18:23:43 volumio volumio[1681]: info: [LastFM] scrobbler initiated! Jun 02 18:23:43 volumio volumio[1681]: info: [LastFM] extended logging: false Jun 02 18:23:43 volumio volumio[1681]: info: [LastFM] try scrobble stream/radio plays: true Jun 02 18:23:43 volumio systemd[1]: Starting Music Player Daemon... Jun 02 18:23:43 volumio volumio[1681]: info: [LastFM] Left init routine Jun 02 18:23:43 volumio volumio[1681]: info: [LastFM] Socket already connected: true Jun 02 18:23:43 volumio volumio[1681]: info: Volumio Calling Home Jun 02 18:23:43 volumio volumio[1681]: info: Discovery: adding 198b4bbd-3d07-43db-9a28-8aeacee0c349 Jun 02 18:23:43 volumio volumio[1681]: info: Discovery: Found device Volumio Jun 02 18:23:43 volumio volumio[1681]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:43 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:43 volumio sudo[1823]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 02 18:23:43 volumio sudo[1823]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:43 volumio sudo[1823]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:43 volumio volumio[1681]: 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: 3 Jun 02 18:23:44 volumio volumio[1681]: info: VolumeController:: Volume=41 Mute =false Jun 02 18:23:44 volumio volumio[1681]: info: CoreStateMachine::pushState Jun 02 18:23:44 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::volumioPushState Jun 02 18:23:44 volumio volumio5-onboarding[1205]: time=2026-06-02T18:23:44.022+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1ac18f0" state=STATUS_STOPPED positionMs=0 volume=41 Jun 02 18:23:44 volumio volumio[1681]: info: MPD Permissions set Jun 02 18:23:44 volumio volumio[1681]: info: MPD Permissions set Jun 02 18:23:44 volumio volumio[1681]: info: Volumio called home Jun 02 18:23:44 volumio volumio[1681]: info: Spotify config file written Jun 02 18:23:44 volumio volumio5-onboarding[1205]: time=2026-06-02T18:23:44.103+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x1ac18f0" id=http://192.168.0.101:8200/MediaItems/232149.flac title="More Than a Feeling" Jun 02 18:23:44 volumio sudo[1830]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 18:23:44 volumio sudo[1830]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:44 volumio systemd[1]: Stopping go-librespot Daemon... Jun 02 18:23:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 02 18:23:44 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 02 18:23:44 volumio systemd[1]: Stopped go-librespot Daemon. Jun 02 18:23:44 volumio volumio[1681]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 02 18:23:44 volumio systemd[1]: Started go-librespot Daemon. Jun 02 18:23:44 volumio go-librespot[1832]: go-librespot daemon starting... Jun 02 18:23:44 volumio sudo[1830]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=info msg="running go-librespot 0.4.0" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="app state loaded" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: No need to fix Spotify hosts Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" 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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=info msg="zeroconf server listening on port 39927" Jun 02 18:23:44 volumio volumio[1681]: info: [LastFM] finished init: Authenticated successfully! Jun 02 18:23:44 volumio volumio[1681]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:23:44 volumio volumio[1681]: SPOTIFY: BQDEhY8gYSYr7neQObHvoSM1Urb_UkgStzy8p4Up_fZv_BdaUIbUYKj1xapzD6wmf9ZJAtezw-6vF4p7VgYzBTvrUhOuUG9vv_pg3xTLnN_Dy4EQ_uRj9qMQuRgN0ozO8MqubyOOMEMLsKl8SgQX6OStqQxSUHzlcW2Asc8NFx51MdZLEny8b6hJ3fttkOW6Z7X7JWibGe-CPLjrW8T6iqfNPss_zm4GXgTKBUKFtajb43kMui-kG5arIoMetJB3y06GDU5vf1BihKSajBnupqclQIm3qG-5hg Jun 02 18:23:44 volumio volumio[1681]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 02 18:23:44 volumio volumio[1681]: info: New Spotify access token = BQDEhY8gYSYr7neQObHvoSM1Urb_UkgStzy8p4Up_fZv_BdaUIbUYKj1xapzD6wmf9ZJAtezw-6vF4p7VgYzBTvrUhOuUG9vv_pg3xTLnN_Dy4EQ_uRj9qMQuRgN0ozO8MqubyOOMEMLsKl8SgQX6OStqQxSUHzlcW2Asc8NFx51MdZLEny8b6hJ3fttkOW6Z7X7JWibGe-CPLjrW8T6iqfNPss_zm4GXgTKBUKFtajb43kMui-kG5arIoMetJB3y06GDU5vf1BihKSajBnupqclQIm3qG-5hg Jun 02 18:23:44 volumio volumio[1681]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:44 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="obtained new client token: AADHSORZVGvnAGtqdGbk42Sy2Kl34GGXOeMfVzZxc73iKCmScKfDls+aySf7rUP6SFN0/dTf4hkH23O6rwvVv/t9PcEKqUKtM7yEbHQUgYrc6HFZ56zi4DY5c3EgDzCkHwhpszNflwtktWBDryfvslH8DYZNFplOMNvHwzBovzaFxpIMbpuiZY+G9It8/9G5c48WhBGBhbOopUhAxKAdv7hoyXzLzYrgiNwP+gw+r35/HeikA4BBFW4=" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="completed keyexchange" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="completed challenge" Jun 02 18:23:44 volumio volumio[1681]: SPOTIFY: User informations: {"account_id":"Rf8p5ogBAa","country":"AT","display_name":"288 GTO","email":"288gto@gmx.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/288_gto"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/288_gto","id":"288_gto","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85467fa7ce35d304790fe5f608","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82467fa7ce35d304790fe5f608","width":64}],"product":"premium","type":"user","uri":"spotify:user:288_gto"} Jun 02 18:23:44 volumio volumio[1681]: info: Spotify Successfully logged in Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 02 18:23:44 volumio volumio[1681]: info: [1780417424808] CoreMusicLibrary::Adding element Spotify Jun 02 18:23:44 volumio volumio[1681]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 02 18:23:44 volumio volumio[1681]: Cannot find translation for source LastFM Jun 02 18:23:44 volumio volumio[1681]: Cannot find translation for source Spotify Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=info msg="authenticated AP" username="28***to" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=info msg="authenticated Login5" username="28***to" Jun 02 18:23:44 volumio go-librespot[1832]: time="2026-06-02T18:23:44+02:00" level=debug msg="initializing zeroconf session" username="28***to" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="dealer connection opened" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=trace msg="starting accesspoint recv loop" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=trace msg="starting dealer recv loop" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=trace msg="received accesspoint ping" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="received connection id: ZTI3MjVmN2YtMTNl...Q0IwMTA4RjU3Ng==" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=trace msg="received accesspoint pong ack" Jun 02 18:23:45 volumio go-librespot[1832]: time="2026-06-02T18:23:45+02:00" level=debug msg="put connect state because NEW_DEVICE" Jun 02 18:23:45 volumio mpd[1828]: Jun 02 18:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 02 18:23:45 volumio volumio[1681]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:45 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:47 volumio volumio[1681]: info: go-librespot daemon successfully initialized Jun 02 18:23:47 volumio systemd[1]: Started Music Player Daemon. Jun 02 18:23:47 volumio sudo[1810]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:47 volumio sudo[1801]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:47 volumio volumio[1681]: info: Completed starting Core Plugins Jun 02 18:23:47 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:47 volumio volumio[1681]: info: ----- MyVolumio plugins startup ---- Jun 02 18:23:47 volumio volumio[1681]: info: ------------------------------------------- Jun 02 18:23:47 volumio volumio[1681]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 02 18:23:47 volumio volumio[1681]: error: MPD error: The expression evaluated to a falsy value: Jun 02 18:23:47 volumio volumio[1681]: assert.ok(self.idling) Jun 02 18:23:47 volumio volumio[1681]: error: The expression evaluated to a falsy value: Jun 02 18:23:47 volumio volumio[1681]: assert.ok(self.idling) Jun 02 18:23:47 volumio volumio[1681]: error: updateQueue error: null Jun 02 18:23:47 volumio volumio[1681]: info: MPD running with PID1828 Jun 02 18:23:47 volumio volumio[1681]: ,establishing connection Jun 02 18:23:47 volumio volumio[1681]: error: updateQueue error: null Jun 02 18:23:48 volumio volumio[1681]: info: Cannot mount NAS audio at system boot, trial number 3 ,retrying in 5 seconds Jun 02 18:23:48 volumio sudo[1868]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 02 18:23:48 volumio sudo[1868]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:48 volumio sudo[1868]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:48 volumio sudo[1870]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 02 18:23:48 volumio sudo[1870]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:48 volumio sudo[1870]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:48 volumio sudo[1874]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 02 18:23:48 volumio sudo[1874]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 18:23:48 volumio sudo[1874]: pam_unix(sudo:session): session closed for user root Jun 02 18:23:48 volumio volumio[1681]: info: Upmpdcli Daemon Started Jun 02 18:23:50 volumio volumio[1681]: info: Initializing connection to go-librespot Websocket Jun 02 18:23:50 volumio go-librespot[1832]: time="2026-06-02T18:23:50+02:00" level=debug msg="new websocket client" Jun 02 18:23:50 volumio volumio[1681]: info: Connection to go-librespot Websocket established Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="handling transfer player command from 0a3ffcb5a5b00010d9c4775126b0e2c22a3f1009" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="resolved context of track" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="shuffled context with seed 10165365655523049557 (len: 1, keep: -1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="loading track (paused: false, position: 11777ms)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=trace msg="emitting websocket event: will_play" Jun 02 18:23:51 volumio volumio[1681]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:7btwmzYKStDASnnx0vubga","uri":"spotify:track:7btwmzYKStDASnnx0vubga","play_origin":"search"}} Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="selected format OGG_VORBIS_320 (1b14835563c9295a7876aec8ec33a4d89a3b91e1)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="requested aes key for file 1b14835563c9295a7876aec8ec33a4d89a3b91e1, gid: 7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="fetched first chunk of 27, total size is 14072484 bytes" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=trace msg="seek to 11777ms (diff: 94ms, samples: 519365, bytes: 434505)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:51 volumio go-librespot[1832]: time="2026-06-02T18:23:51+02:00" level=debug msg="created new output device" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=info msg="loaded track \"Industrial Disease\" (paused: false, position: 11777ms, duration: 348440ms, prefetched: false)" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=trace msg="scheduling prefetch in 307s" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=trace msg="emitting websocket event: metadata" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=trace msg="emitting websocket event: active" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="sending successful reply for dealer request" Jun 02 18:23:52 volumio volumio[1681]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7btwmzYKStDASnnx0vubga","name":"Industrial Disease","artist_names":["Dire Straits"],"album_name":"Love Over Gold","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0221ebb685af8162c4ed890852","position":11777,"duration":348440,"release_date":"year:1982 month:9 day:20","track_number":3,"disc_number":1}} Jun 02 18:23:52 volumio volumio[1681]: SPOTIFY: received: {"type":"active","data":null} Jun 02 18:23:52 volumio volumio[1681]: info: Aligning Spotify Volume to Volumio Volume Jun 02 18:23:52 volumio volumio[1681]: info: CoreCommandRouter::volumioGetState Jun 02 18:23:52 volumio volumio[1681]: info: CorePlayQueue::getTrack 0 Jun 02 18:23:52 volumio volumio[1681]: info: Setting Spotify Volume from Volumio: 41 Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=trace msg="emitting websocket event: playing" Jun 02 18:23:52 volumio volumio[1681]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:7btwmzYKStDASnnx0vubga","uri":"spotify:track:7btwmzYKStDASnnx0vubga","resume":false,"play_origin":"search"}} Jun 02 18:23:52 volumio volumio[1681]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 18:23:52 volumio volumio[1681]: TypeError: Cannot read property 'service' of undefined Jun 02 18:23:52 volumio volumio[1681]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Jun 02 18:23:52 volumio volumio[1681]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Jun 02 18:23:52 volumio volumio[1681]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Jun 02 18:23:52 volumio volumio[1681]: at WebSocket.emit (events.js:315:20) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.emit (events.js:315:20) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 02 18:23:52 volumio volumio[1681]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 02 18:23:52 volumio volumio[1681]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 02 18:23:52 volumio volumio[1681]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 02 18:23:52 volumio volumio[1681]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 02 18:23:52 volumio volumio[1681]: at Socket.emit (events.js:315:20) Jun 02 18:23:52 volumio volumio[1681]: at addChunk (internal/streams/readable.js:309:12) Jun 02 18:23:52 volumio volumio[1681]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 02 18:23:52 volumio volumio[1681]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:52 volumio go-librespot[1832]: time="2026-06-02T18:23:52+02:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:7btwmzYKStDASnnx0vubga" Jun 02 18:23:52 volumio sudo[1886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-06-02 18:22 Jun 02 18:23:52 volumio sudo[1886]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"