Oct 13 15:24:37 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 13 15:24:37 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 13 15:24:37 volumio systemd[1]: setdatetime-helper.service: Consumed 2.198s CPU time. Oct 13 15:24:37 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Oct 13 15:24:37 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Oct 13 15:24:37 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Oct 13 15:24:37 volumio ntpd[974]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 13 15:24:37 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Oct 13 15:24:37 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Oct 13 15:24:37 volumio ntpd[974]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 195.32.70.195 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 37.247.53.178 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 151.22.209.90 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 93.94.88.51 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 2a00:6d41:200:2::11 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 2600:3c0b::f03c:94ff:fe16:7f5a Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 2a00:6d41:200:2::14 Oct 13 15:24:37 volumio ntpd[974]: DNS: Pool taking: 2a00:6d40:72:100::5c5 Oct 13 15:24:37 volumio ntpd[974]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Oct 13 15:24:37 volumio nmbd[1019]: [2026/10/13 15:24:37.640932, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Oct 13 15:24:37 volumio nmbd[1019]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.186 for name WORKGROUP<1d>. Oct 13 15:24:37 volumio nmbd[1019]: This response was from IP 192.168.1.103, reporting an IP address of 192.168.1.103. Oct 13 15:24:38 volumio ntpd[974]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 13 15:24:38 volumio ntpd[974]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Oct 13 15:24:38 volumio ntpd[974]: DNS: Pool skipping: 151.22.209.90 Oct 13 15:24:38 volumio ntpd[974]: DNS: Pool skipping: 37.247.53.178 Oct 13 15:24:38 volumio ntpd[974]: DNS: Pool taking: 95.110.254.234 Oct 13 15:24:38 volumio ntpd[974]: DNS: Pool skipping: 93.94.88.51 Oct 13 15:24:38 volumio ntpd[974]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Oct 13 15:24:38 volumio winbindd[1151]: [2026/10/13 15:24:38.386354, 0] ../../source3/winbindd/winbindd_idmap.c:372(wb_parent_idmap_setup_lookupname_done) Oct 13 15:24:38 volumio winbindd[1151]: wb_parent_idmap_setup_lookupname_done: Lookup domain name 'VOLUMIO' failed 'NT_STATUS_IO_TIMEOUT' Oct 13 15:24:38 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Oct 13 15:24:38 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Oct 13 15:24:38 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Oct 13 15:24:38 volumio volumio-remote-updater[674]: [2026-10-13 15:24:38] [connect] Successful connection Oct 13 15:24:38 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Oct 13 15:24:38 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Oct 13 15:24:38 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Oct 13 15:24:38 volumio systemd[1]: Startup finished in 15.668s (kernel) + 18.477s (userspace) = 34.146s. Oct 13 15:24:39 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:24:39 volumio volumio[1056]: info: ----- Volumio3 ---- Oct 13 15:24:39 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:24:39 volumio volumio[1056]: info: ----- System startup ---- Oct 13 15:24:39 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:24:39 volumio ntpd[974]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Oct 13 15:24:39 volumio ntpd[974]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Oct 13 15:24:39 volumio ntpd[974]: DNS: Pool taking: 212.45.144.206 Oct 13 15:24:39 volumio ntpd[974]: DNS: Pool taking: 172.232.209.103 Oct 13 15:24:39 volumio ntpd[974]: DNS: Pool skipping: 185.19.184.35 Oct 13 15:24:39 volumio ntpd[974]: DNS: Pool taking: 89.46.74.148 Oct 13 15:24:39 volumio ntpd[974]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Oct 13 15:24:40 volumio volumio[1056]: info: MYVOLUMIO Environment detected Oct 13 15:24:40 volumio volumio[1056]: info: Plugin folders cleanup Oct 13 15:24:40 volumio volumio[1056]: info: Scanning into folder /volumio/app/plugins/ Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category audio_interface Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category miscellanea Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category music_service Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category plugins.json Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category system_controller Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category user_interface Oct 13 15:24:40 volumio volumio[1056]: info: Scanning into folder /data/plugins/ Oct 13 15:24:40 volumio volumio[1056]: info: Scanning category music_service Oct 13 15:24:40 volumio volumio[1056]: info: Plugin folders cleanup completed Oct 13 15:24:40 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:24:40 volumio volumio[1056]: info: ----- Core plugins startup ---- Oct 13 15:24:40 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:24:40 volumio volumio[1056]: info: Loading plugins from folder /volumio/app/plugins/ Oct 13 15:24:40 volumio volumio[1056]: info: Adding plugin upnp to MyMusic Plugins Oct 13 15:24:40 volumio volumio[1056]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 13 15:24:40 volumio volumio[1056]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 13 15:24:40 volumio volumio[1056]: info: Loading plugins from folder /data/plugins/ Oct 13 15:24:40 volumio volumio[1056]: info: Loading plugin "system"... Oct 13 15:24:41 volumio volumio[1056]: info: Loading plugin "appearance"... Oct 13 15:24:41 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Oct 13 15:24:41 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:24:41 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:24:41 volumio upmpdcli[1241]: Could not open config: /tmp/upmpdcli.conf Oct 13 15:24:41 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:24:41 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 13 15:24:43 volumio volumio[1056]: info: Loading plugin "network"... Oct 13 15:24:43 volumio volumio[1056]: info: Refreshing Cached IP Addresses Oct 13 15:24:44 volumio ntpd[974]: CLOCK: time stepped by 0.838723 Oct 13 15:24:44 volumio ntpd[974]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 13 15:24:44 volumio volumio[1056]: info: Loading plugin "services"... Oct 13 15:24:44 volumio volumio[1056]: info: Loading plugin "volumio5onboarding"... Oct 13 15:24:44 volumio sudo[1245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 13 15:24:44 volumio sudo[1245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio sudo[1245]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:44 volumio sudo[1244]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 13 15:24:44 volumio sudo[1244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio volumio[1056]: info: Loading plugin "alsa_controller"... Oct 13 15:24:44 volumio sudo[1244]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:44 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 15:24:44 volumio volumio[1056]: info: Loading plugin "wizard"... Oct 13 15:24:44 volumio volumio[1056]: info: Loading plugin "networkfs"... Oct 13 15:24:44 volumio sudo[1274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/GrooveSalad /mnt/NAS/GrooveSalad Oct 13 15:24:44 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio sudo[1276]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/GrooveSaladClassic /mnt/NAS/GrooveSaladClassic Oct 13 15:24:44 volumio sudo[1276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio sudo[1278]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/Musica /mnt/NAS/Musica Oct 13 15:24:44 volumio sudo[1278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio sudo[1280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/RadioParadiseRock /mnt/NAS/RadioParadiseRock Oct 13 15:24:44 volumio sudo[1292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/Afro_70-80 /mnt/NAS/Afro_70-80 Oct 13 15:24:44 volumio sudo[1292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio sudo[1280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:44 volumio kernel: netfs: FS-Cache loaded Oct 13 15:24:44 volumio volumio[1056]: info: Starting Udev Watcher for removable devices Oct 13 15:24:44 volumio sudo[1287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=massimo,password=c6x9pmqrkt,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,x-systemd.automount,x-systemd.device-timeout=30 //192.168.1.88/Radio80 /mnt/NAS/Radio80 Oct 13 15:24:44 volumio sudo[1287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:45 volumio volumio[1056]: info: Ignoring mount for partition: boot Oct 13 15:24:45 volumio volumio[1056]: info: Ignoring mount for partition: volumio Oct 13 15:24:45 volumio volumio[1056]: info: Ignoring mount for partition: volumio_data Oct 13 15:24:45 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 13 15:24:45 volumio volumio[1056]: info: Loading plugin "volumio_command_line_client"... Oct 13 15:24:45 volumio kernel: Key type cifs.spnego registered Oct 13 15:24:45 volumio kernel: Key type cifs.idmap registered Oct 13 15:24:45 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. Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/Afro_70-80 Oct 13 15:24:45 volumio volumio[1056]: info: Plugin upnp is not enabled Oct 13 15:24:45 volumio volumio[1056]: info: Loading plugin "my_music"... Oct 13 15:24:45 volumio volumio[1056]: info: Loading plugin "mpd"... Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/GrooveSaladClassic Oct 13 15:24:45 volumio sudo[1276]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/Musica Oct 13 15:24:45 volumio sudo[1292]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:45 volumio sudo[1278]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/GrooveSalad Oct 13 15:24:45 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/RadioParadiseRock Oct 13 15:24:45 volumio kernel: CIFS: Attempting to mount //192.168.1.88/Radio80 Oct 13 15:24:45 volumio sudo[1280]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:45 volumio sudo[1287]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:46 volumio volumio[1056]: info: Plugin upnp_browser is not enabled Oct 13 15:24:46 volumio volumio[1056]: info: Loading plugin "alarm-clock"... Oct 13 15:24:46 volumio volumio[1056]: info: Plugin airplay_emulation is not enabled Oct 13 15:24:46 volumio volumio[1056]: info: Loading plugin "last_100"... Oct 13 15:24:46 volumio volumio[1056]: info: Loading plugin "webradio"... Oct 13 15:24:48 volumio volumio[1056]: info: Loading plugin "i2s_dacs"... Oct 13 15:24:48 volumio volumio[1056]: info: I2S DAC not set, start Auto-detection Oct 13 15:24:48 volumio volumio[1056]: info: Loading plugin "volumiodiscovery"... Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 13 15:24:48 volumio node[1056]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** For more information see Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 13 15:24:48 volumio volumio[1056]: *** WARNING *** For more information see Oct 13 15:24:48 volumio node[1056]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 13 15:24:48 volumio node[1056]: *** WARNING *** For more information see Oct 13 15:24:48 volumio node[1056]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 13 15:24:48 volumio node[1056]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 13 15:24:48 volumio node[1056]: *** WARNING *** For more information see Oct 13 15:24:48 volumio volumio[1056]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 13 15:24:48 volumio volumio[1056]: info: Discovery: Started advertising with name: Volumio Oct 13 15:24:48 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 13 15:24:48 volumio volumio[1056]: info: Loading plugin "spop"... Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "outputs"... Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "albumart"... Oct 13 15:24:52 volumio volumio[1056]: info: Plugin example_plugin is not enabled Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "inputs"... Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "updater_comm"... Oct 13 15:24:52 volumio volumio[1056]: info: Plugin mpdemulation is not enabled Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "rest_api"... Oct 13 15:24:52 volumio volumio[1056]: info: Loading plugin "websocket"... Oct 13 15:24:52 volumio volumio[1056]: info: Starting Socket.io Server version 1.7.4 Oct 13 15:24:52 volumio volumio[1056]: info: Loading i18n strings for locale en Oct 13 15:24:52 volumio volumio[1056]: Updating browse sources language Oct 13 15:24:52 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::initPlayerControls Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: Express server listening on port 3000 Oct 13 15:24:53 volumio volumio[1056]: [Metrics] WebUI: 15s 2.00ms Oct 13 15:24:53 volumio volumio[1056]: info: CoreStateMachine::resetVolumioState Oct 13 15:24:53 volumio volumio[1056]: info: CoreStateMachine::getcurrentVolume Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::volumioRetrievevolume Oct 13 15:24:53 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 15:24:53 volumio volumio[1056]: info: Volumio Network Manager: Network status updated: 1 Oct 13 15:24:54 volumio volumio[1056]: info: VolumeController:: Volume=50 Mute =false Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::pushState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioPushState Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::updateTrackBlock Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrackBlock Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioRetrievevolume Oct 13 15:24:54 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::setRepeat false single undefined Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::pushState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioPushState Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::setRandom true Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::pushState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioPushState Oct 13 15:24:54 volumio volumio[1350]: Forking 3 albumart workers Oct 13 15:24:54 volumio volumio[1056]: info: Setting Device type: Raspberry PI Oct 13 15:24:54 volumio volumio-remote-updater[674]: [2026-10-13 15:24:54] [connect] Successful connection Oct 13 15:24:54 volumio volumio[1056]: info: VolumeController:: Volume=50 Mute =false Oct 13 15:24:54 volumio volumio[1056]: info: CoreStateMachine::pushState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioPushState Oct 13 15:24:54 volumio volumio-remote-updater[674]: [2026-10-13 15:24:54] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1791897894 101 Oct 13 15:24:54 volumio volumio[1056]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Oct 13 15:24:54 volumio volumio[1056]: info: Discovery: adding 602bf9c3-1611-473e-bad3-b37163e7d223 Oct 13 15:24:54 volumio volumio[1056]: info: Discovery: Found device Volumio Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:54 volumio volumio[1056]: info: Completed loading Core Plugins Oct 13 15:24:54 volumio volumio[1056]: info: Preparing to generate the ALSA configuration file Oct 13 15:24:54 volumio volumio[1056]: info: Discovery: this is already registered, 602bf9c3-1611-473e-bad3-b37163e7d223 Oct 13 15:24:54 volumio volumio[1056]: info: Discovery: Found device Volumio Oct 13 15:24:54 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:24:54 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:24:55 volumio volumio[1056]: info: Asound.conf file unchanged, so no further update is needed Oct 13 15:24:55 volumio volumio[1056]: info: Output device has changed, restarting MPD Oct 13 15:24:55 volumio volumio[1056]: info: ___________ START PLUGINS ___________ Oct 13 15:24:55 volumio sudo[1420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 13 15:24:55 volumio sudo[1420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:55 volumio sudo[1422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 13 15:24:55 volumio volumio[1056]: info: ControllerMpd::onStart: Initializing MPD Oct 13 15:24:55 volumio volumio[1056]: info: Creating MPD Configuration file Oct 13 15:24:55 volumio sudo[1420]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:55 volumio sudo[1422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:55 volumio sudo[1424]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Oct 13 15:24:55 volumio sudo[1424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:55 volumio volumio[1056]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 15:24:55 volumio volumio[1056]: info: [1791897895620] CoreMusicLibrary::Adding element Last_100 Oct 13 15:24:55 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 15:24:55 volumio volumio[1056]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 15:24:55 volumio volumio[1056]: info: [1791897895700] CoreMusicLibrary::Adding element Webradio Oct 13 15:24:55 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 15:24:55 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 15:24:55 volumio sudo[1427]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 13 15:24:55 volumio sudo[1427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:55 volumio sudo[1431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 13 15:24:55 volumio sudo[1431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:24:55 volumio volumio[1056]: info: Initializing BBC Radios Oct 13 15:24:55 volumio sudo[1427]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:55 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 13 15:24:55 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 13 15:24:55 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Oct 13 15:24:55 volumio sudo[1424]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:56 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 13 15:24:56 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 13 15:24:56 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 13 15:24:56 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 13 15:24:56 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 13 15:24:56 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 13 15:24:56 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 13 15:24:56 volumio sudo[1446]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 13 15:24:56 volumio sudo[1446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 13 15:24:56 volumio sudo[1458]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 13 15:24:56 volumio sudo[1446]: pam_unix(sudo:session): session closed for user root Oct 13 15:24:56 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 13 15:24:56 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 15:24:56 volumio volumio5-onboarding[1442]: time=2026-10-13T15:24:56.634+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Oct 13 15:24:56 volumio volumio[1056]: info: Creating Spotify config file Oct 13 15:24:56 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:24:57 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Oct 13 15:24:57 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:24:57 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:24:57 volumio upmpdcli[1463]: Could not open config: /tmp/upmpdcli.conf Oct 13 15:24:57 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:24:57 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 13 15:24:58 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Oct 13 15:25:00 volumio volumio[1056]: info: Volumio Calling Home Oct 13 15:25:04 volumio volumio[1056]: info: MPD Permissions set Oct 13 15:25:04 volumio volumio[1056]: info: MPD Permissions set Oct 13 15:25:04 volumio mpd[1459]: 2026-10-13T15:25:04 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 13 15:25:04 volumio volumio[1056]: 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 Oct 13 15:25:04 volumio volumio[1056]: info: Volumio called home Oct 13 15:25:04 volumio volumio[1056]: info: Spotify config file written Oct 13 15:25:04 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 13 15:25:04 volumio sudo[1422]: pam_unix(sudo:session): session closed for user root Oct 13 15:25:04 volumio sudo[1474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 13 15:25:04 volumio sudo[1474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 13 15:25:04 volumio sudo[1431]: pam_unix(sudo:session): session closed for user root Oct 13 15:25:04 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 15:25:04 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 13 15:25:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:04 volumio go-librespot[1482]: go-librespot daemon starting... Oct 13 15:25:04 volumio sudo[1474]: pam_unix(sudo:session): session closed for user root Oct 13 15:25:05 volumio volumio[1377]: Starting albumart workers Oct 13 15:25:05 volumio go-librespot[1487]: time="2026-10-13T15:25:05+02:00" level=info msg="running go-librespot 0.7.1" Oct 13 15:25:05 volumio go-librespot[1487]: time="2026-10-13T15:25:05+02:00" level=debug msg="app state loaded" Oct 13 15:25:05 volumio go-librespot[1487]: time="2026-10-13T15:25:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 13 15:25:06 volumio volumio[1376]: Starting albumart workers Oct 13 15:25:06 volumio volumio[1056]: 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 Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25: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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 13 15:25:06 volumio volumio[1056]: info: Received Get System Info Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 15:25:06 volumio volumio[1056]: info: Discovery: Getting this device information Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:25:06 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=info msg="zeroconf server listening on port 45271" Oct 13 15:25:06 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:06.560+02:00 level=INFO msg="system info for 2ed8822610c7a0641bcf6aa7cde370f5" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 13 15:25:06 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:06.607+02:00 level=INFO msg="bootstrapping state" hasInternet=true Oct 13 15:25:06 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 13 15:25:06 volumio volumio[1056]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=debug msg="obtained new client token: AAFoscovcT0ewnzffQW7jaP4DV1Qv2FBrlMLK9+O4RTkCt8hZAh6wbWf3sGPNkoMwm8PqzDPASLV/5L7ZdcLVF/nJRSHRAef6utwlJFvCgRTXG0vLbonDx7lXUPHNe1FBtAFQsOveUxIM8bLm4pfJ5c8WZsayQs4YFwBVzWZi7ptALPijifaIH6vG86gXM8WqRVMk6sMGyP0EITf1klul/V5JP1LhuKShE+zxO7D4E5mIZrvgiIqdAt9" Oct 13 15:25:06 volumio go-librespot[1487]: time="2026-10-13T15:25:06+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:06 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio go-librespot[1487]: time="2026-10-13T15:25:07+02:00" level=debug msg="completed keyexchange" Oct 13 15:25:07 volumio go-librespot[1487]: time="2026-10-13T15:25:07+02:00" level=debug msg="completed challenge" Oct 13 15:25:07 volumio go-librespot[1487]: time="2026-10-13T15:25:07+02:00" level=info msg="authenticated AP" username="zz**p5" Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio go-librespot[1487]: time="2026-10-13T15:25:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Oct 13 15:25:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 13 15:25:07 volumio volumio[1056]: info: No need to fix Spotify hosts Oct 13 15:25:07 volumio volumio[1374]: Starting albumart workers Oct 13 15:25:08 volumio volumio[1056]: info: Received Get System Info Oct 13 15:25:08 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 15:25:08 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 15:25:08 volumio volumio[1056]: info: Discovery: Getting this device information Oct 13 15:25:08 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:25:08 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:25:08 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 15:25:08 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 13 15:25:08 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 13 15:25:08 volumio systemd[1]: setdatetime-helper.service: Consumed 1.000s CPU time. Oct 13 15:25:09 volumio volumio[1056]: info: Completed starting Core Plugins Oct 13 15:25:09 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:25:09 volumio volumio[1056]: info: ----- MyVolumio plugins startup ---- Oct 13 15:25:09 volumio volumio[1056]: info: ------------------------------------------- Oct 13 15:25:09 volumio volumio[1056]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 13 15:25:09 volumio volumio-remote-updater[674]: Test mode disabled Oct 13 15:25:09 volumio volumio-remote-updater[674]: Alpha mode disabled Oct 13 15:25:09 volumio volumio-remote-updater[674]: Alpha legacy test mode disabled Oct 13 15:25:10 volumio volumio[1056]: info: New Spotify access tokenBQCwe0Jko-... Oct 13 15:25:10 volumio volumio[1056]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 13 15:25:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 13 15:25:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:10 volumio go-librespot[1549]: go-librespot daemon starting... Oct 13 15:25:10 volumio go-librespot[1553]: time="2026-10-13T15:25:10+02:00" level=info msg="running go-librespot 0.7.1" Oct 13 15:25:10 volumio go-librespot[1553]: time="2026-10-13T15:25:10+02:00" level=debug msg="app state loaded" Oct 13 15:25:10 volumio go-librespot[1553]: time="2026-10-13T15:25:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+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]" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+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]" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+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]" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=info msg="zeroconf server listening on port 37665" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 13 15:25:11 volumio volumio[1056]: error: MPD error: The expression evaluated to a falsy value: Oct 13 15:25:11 volumio volumio[1056]: assert.ok(self.idling) Oct 13 15:25:11 volumio volumio[1056]: error: The expression evaluated to a falsy value: Oct 13 15:25:11 volumio volumio[1056]: assert.ok(self.idling) Oct 13 15:25:11 volumio volumio[1056]: info: MPD running with PID1459 Oct 13 15:25:11 volumio volumio[1056]: ,establishing connection Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=debug msg="obtained new client token: AAGze+piFEZe0LTGZ16f+ExxzhOh+mtzThckJ9TCTTwyeRVJOOOPsN5C2CNS4xo3tyGqspFLHuNzl5I3S45LqXgh87XkGrEJTTWwCkxxHM0cATKFfbpuewzlOxOVMZzCRaHtwD0eyKbKSuYwCaoQllv97jjL9H7o5ldVX+Go+6hmkkR6escV7iJBAmy/ecEbWcNeoA+Fx/yP9Jw98S6GS5KcZwgSYU+jf+rgJP/2Eussc2nBRrbIr0ja" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=debug msg="completed keyexchange" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=debug msg="completed challenge" Oct 13 15:25:11 volumio go-librespot[1553]: time="2026-10-13T15:25:11+02:00" level=info msg="authenticated AP" username="zz**p5" Oct 13 15:25:12 volumio go-librespot[1553]: time="2026-10-13T15:25:12+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Oct 13 15:25:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 13 15:25:12 volumio volumio[1056]: error: updateQueue error: null Oct 13 15:25:12 volumio volumio[1056]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 13 15:25:12 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 13 15:25:12 volumio volumio[1056]: info: go-librespot daemon successfully initialized Oct 13 15:25:12 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 15:25:12 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:12.872+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" Oct 13 15:25:12 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:12.873+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" Oct 13 15:25:12 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:12.873+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" Oct 13 15:25:12 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Oct 13 15:25:12 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:25:13 volumio volumio[1056]: error: updateQueue error: null Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 15:25:13 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 13 15:25:13 volumio upmpdcli[1572]: Could not open config: /tmp/upmpdcli.conf Oct 13 15:25:13 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:13 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 13 15:25:13 volumio volumio[1056]: info: Received Get System Info Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 13 15:25:13 volumio volumio[1056]: info: Discovery: Getting this device information Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:25:13 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 13 15:25:13 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:13.464+02:00 level=INFO msg="enabling local network discovery" Oct 13 15:25:13 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:13.499+02:00 level=INFO msg="enabling BLE discovery" Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::volumioGetState Oct 13 15:25:13 volumio volumio[1056]: info: CorePlayQueue::getTrack 0 Oct 13 15:25:13 volumio volumio[1056]: SPOTIFY: User informations: {"account_id":"YfcfFybVvX","country":"IT","display_name":"zz00p5","email":"massimomilan74@hotmail.it","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/zz00p5"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/zz00p5","id":"zz00p5","images":[],"product":"premium","type":"user","uri":"spotify:user:zz00p5"} Oct 13 15:25:13 volumio volumio[1056]: info: Spotify Successfully logged in Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 13 15:25:13 volumio volumio[1056]: info: [1791897913859] CoreMusicLibrary::Adding element Spotify Oct 13 15:25:13 volumio volumio[1056]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 13 15:25:13 volumio volumio[1056]: Cannot find translation for source Spotify Oct 13 15:25:14 volumio volumio5-onboarding[1442]: time=2026-10-13T15:25:14.523+02:00 level=INFO msg="service successfully established" component=discovery/localnet Oct 13 15:25:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Oct 13 15:25:15 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Oct 13 15:25:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:15 volumio go-librespot[1580]: go-librespot daemon starting... Oct 13 15:25:15 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Oct 13 15:25:15 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=info msg="running go-librespot 0.7.1" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=debug msg="app state loaded" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 13 15:25:15 volumio volumio[1056]: info: Initializing connection to go-librespot Websocket Oct 13 15:25:15 volumio volumio[1056]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=info msg="zeroconf server listening on port 45375" Oct 13 15:25:15 volumio go-librespot[1581]: time="2026-10-13T15:25:15+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=debug msg="new websocket client" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=debug msg="obtained new client token: AAGSNrxPgtfBgAcw6NtfJgA0x+gXl1EPCGh/NCM6s8Jp4twfBB8Hapgd9zcQS+w9odhu7maW0LVjHAceZOFXrdxoaOzruu03tJmU/2INJVl7/DpH4cP2Vm3epZCTSbTSVVIPqlAMpxAbYSdzIreEiU7oH39+j9gc4YqIB/ANdHf2/SjsbCgW3eW9D+Sd5e6qYMgW2O3qwfr2kjHyBUBYDlBhqsE4uScaat7/bVWkOtxo0NS/+2KAiA==" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 13 15:25:16 volumio volumio[1056]: info: Connection to go-librespot Websocket established Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=debug msg="completed keyexchange" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=debug msg="completed challenge" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=info msg="authenticated AP" username="zz**p5" Oct 13 15:25:16 volumio go-librespot[1581]: time="2026-10-13T15:25:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Oct 13 15:25:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 13 15:25:17 volumio volumio[1056]: info: Connection to go-librespot Websocket closed Oct 13 15:25:19 volumio volumio[1056]: info: Getting Spotify volume Oct 13 15:25:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 13 15:25:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:20 volumio go-librespot[1601]: go-librespot daemon starting... Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=info msg="running go-librespot 0.7.1" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=debug msg="app state loaded" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 13 15:25:20 volumio volumio[1056]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 15:25:20 volumio volumio[1056]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 13 15:25:20 volumio volumio[1056]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 13 15:25:20 volumio volumio[1056]: errno: -111, Oct 13 15:25:20 volumio volumio[1056]: code: 'ECONNREFUSED', Oct 13 15:25:20 volumio volumio[1056]: syscall: 'connect', Oct 13 15:25:20 volumio volumio[1056]: address: '127.0.0.1', Oct 13 15:25:20 volumio volumio[1056]: port: 9879, Oct 13 15:25:20 volumio volumio[1056]: response: undefined Oct 13 15:25:20 volumio volumio[1056]: } Oct 13 15:25:20 volumio volumio[1056]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=info msg="zeroconf server listening on port 36819" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 13 15:25:20 volumio go-librespot[1602]: time="2026-10-13T15:25:20+02:00" level=debug msg="obtained new client token: AAECMv8+vUlsHeSiJIkCcnAOFZNYJ8Y7tTcOTd+snSbKEV1wAGSDqR7zMo/Ht/cyGSngqN0Zl+e+zCHOQnJtLbnfZNDhUXj4L4oslYrvYZLww9vj9cnG2hLIX63AGEcnBP2VEQne8ICE08+prXDn4ffE4lDhSWzhmrOOkqoN7dxLPaYWslErkD25JzO7pRoZABWnqYUgqFFxdriCmlMskRY9fxGAZSrbv4/0QhNcc0FNREttWgcqTvJZ" Oct 13 15:25:21 volumio go-librespot[1602]: time="2026-10-13T15:25:21+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 13 15:25:21 volumio go-librespot[1602]: time="2026-10-13T15:25:21+02:00" level=debug msg="completed keyexchange" Oct 13 15:25:21 volumio go-librespot[1602]: time="2026-10-13T15:25:21+02:00" level=debug msg="completed challenge" Oct 13 15:25:21 volumio go-librespot[1602]: time="2026-10-13T15:25:21+02:00" level=info msg="authenticated AP" username="zz**p5" Oct 13 15:25:21 volumio go-librespot[1602]: time="2026-10-13T15:25:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Oct 13 15:25:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 13 15:25:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 13 15:25:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 13 15:25:24 volumio go-librespot[1624]: go-librespot daemon starting... Oct 13 15:25:24 volumio go-librespot[1625]: time="2026-10-13T15:25:24+02:00" level=info msg="running go-librespot 0.7.1" Oct 13 15:25:24 volumio go-librespot[1625]: time="2026-10-13T15:25:24+02:00" level=debug msg="app state loaded" Oct 13 15:25:24 volumio go-librespot[1625]: time="2026-10-13T15:25:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+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]" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+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]" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+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]" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=info msg="zeroconf server listening on port 39963" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=debug msg="obtained new client token: AAH1JT9lhoNFL8ux1/+xrqZ11cOajJv0bD96RTpyT2Mq1giFry0OMS9M8P72dsPotdHLfAMb2pnxmJcNbrQC60jLC6lZg1TfiNGXEzY3QmwX+WvZn0laJN4uGhX+SRpqH9wrLAqAcuZhu0Pm7BsAj7tbf7o6SoOnTdOTC5K/F+pN5BZ/ipfu9pbuWeNu7P7YVF1pKHVvH9q16ayI9WKIN/yYjz+vVWyjHVDULzbv9sy8zCHmQf5mydTB" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=debug msg="completed keyexchange" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=debug msg="completed challenge" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=info msg="authenticated AP" username="zz**p5" Oct 13 15:25:25 volumio go-librespot[1625]: time="2026-10-13T15:25:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Oct 13 15:25:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 13 15:25:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 13 15:25:26 volumio sudo[1650]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-13 15:24' Oct 13 15:25:26 volumio sudo[1650]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"