Aug 30 08:46:01 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:46:01 volumio volumio[1334]: info: ----- Volumio3 ---- Aug 30 08:46:01 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:46:01 volumio volumio[1334]: info: ----- System startup ---- Aug 30 08:46:01 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:46:01 volumio wpa_supplicant[1318]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Aug 30 08:46:02 volumio volumio[1334]: info: MYVOLUMIO Environment detected Aug 30 08:46:02 volumio bash[1140]: setdatetime-helper: all HTTPS Date fallbacks failed Aug 30 08:46:02 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 30 08:46:02 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 30 08:46:02 volumio volumio[1334]: info: Plugin folders cleanup Aug 30 08:46:02 volumio volumio[1334]: info: Scanning into folder /volumio/app/plugins/ Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category audio_interface Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category miscellanea Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category music_service Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category plugins.json Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category system_controller Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category user_interface Aug 30 08:46:02 volumio volumio[1334]: info: Scanning into folder /data/plugins/ Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category audio_interface Aug 30 08:46:02 volumio volumio[1334]: info: Scanning category music_service Aug 30 08:46:02 volumio volumio[1334]: info: Plugin folders cleanup completed Aug 30 08:46:02 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:46:02 volumio volumio[1334]: info: ----- Core plugins startup ---- Aug 30 08:46:02 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:46:02 volumio volumio[1334]: info: Loading plugins from folder /volumio/app/plugins/ Aug 30 08:46:02 volumio volumio[1334]: info: Adding plugin upnp to MyMusic Plugins Aug 30 08:46:02 volumio volumio[1334]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 30 08:46:02 volumio volumio[1334]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 30 08:46:02 volumio volumio[1334]: info: Loading plugins from folder /data/plugins/ Aug 30 08:46:02 volumio volumio[1334]: info: Loading plugin "system"... Aug 30 08:46:02 volumio volumio[1334]: info: Loading plugin "appearance"... Aug 30 08:46:02 volumio dhcpcd[899]: eth0: leased 192.168.111.122 for infinity Aug 30 08:46:02 volumio avahi-daemon[884]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.111.122. Aug 30 08:46:02 volumio avahi-daemon[884]: New relevant interface eth0.IPv4 for mDNS. Aug 30 08:46:02 volumio avahi-daemon[884]: Registering new address record for 192.168.111.122 on eth0.IPv4. Aug 30 08:46:02 volumio dhcpcd[899]: eth0: adding route to 192.168.111.0/24 Aug 30 08:46:02 volumio dhcpcd[899]: eth0: adding default route via 192.168.111.1 Aug 30 08:46:02 volumio systemd[1]: welcome.service: Deactivated successfully. Aug 30 08:46:02 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 30 08:46:02 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 30 08:46:02 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 30 08:46:02 volumio welcome[1509]: Resolved ip:[1] 192.168.111.122 Aug 30 08:46:02 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 30 08:46:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 30 08:46:02 volumio dhcpcd[880]: eth0: leased 192.168.111.122 for infinity Aug 30 08:46:02 volumio sh[864]: eth0: leased 192.168.111.122 for infinity Aug 30 08:46:02 volumio sh[864]: eth0: adding route to 192.168.111.0/24 Aug 30 08:46:02 volumio sh[864]: eth0: adding default route via 192.168.111.1 Aug 30 08:46:02 volumio dhcpcd[880]: eth0: adding route to 192.168.111.0/24 Aug 30 08:46:02 volumio dhcpcd[880]: eth0: adding default route via 192.168.111.1 Aug 30 08:46:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 30 08:46:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 30 08:46:02 volumio systemd[1]: welcome.service: Deactivated successfully. Aug 30 08:46:02 volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 30 08:46:02 volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 30 08:46:03 volumio sh[864]: forked to background, child pid 879 Aug 30 08:46:03 volumio systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 30 08:46:03 volumio welcome[1531]: Resolved ip:[1] 192.168.111.122 Aug 30 08:46:03 volumio systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 30 08:46:03 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 30 08:46:03 volumio systemd[1]: Started nmbd.service - Samba NMB Daemon. Aug 30 08:46:03 volumio systemd[1]: Starting winbind.service - Samba Winbind Daemon... Aug 30 08:46:03 volumio ifplugd(eth0)[1158]: client: ifup: interface eth0 already configured Aug 30 08:46:03 volumio sh[1582]: eth0=eth0 Aug 30 08:46:03 volumio ifplugd(eth0)[1158]: Program executed successfully. Aug 30 08:46:03 volumio winbindd[1583]: [2026/08/30 08:46:03.626453, 0] ../../source3/winbindd/winbindd.c:1440(main) Aug 30 08:46:03 volumio winbindd[1583]: winbindd version 4.17.12-Debian started. Aug 30 08:46:03 volumio winbindd[1583]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 30 08:46:03 volumio winbindd[1583]: [2026/08/30 08:46:03.671268, 0] ../../source3/winbindd/winbindd_cache.c:3117(initialize_winbindd_cache) Aug 30 08:46:03 volumio winbindd[1583]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Aug 30 08:46:03 volumio systemd[1]: Started winbind.service - Samba Winbind Daemon. Aug 30 08:46:03 volumio systemd[1]: Starting smbd.service - Samba SMB Daemon... Aug 30 08:46:04 volumio smbd[1602]: [2026/08/30 08:46:04.090697, 0] ../../source3/smbd/server.c:1741(main) Aug 30 08:46:04 volumio smbd[1602]: smbd version 4.17.12-Debian started. Aug 30 08:46:04 volumio smbd[1602]: Copyright Andrew Tridgell and the Samba Team 1992-2022 Aug 30 08:46:04 volumio ntpd[1181]: IO: Listen normally on 3 eth0 192.168.111.122:123 Aug 30 08:46:04 volumio ntpd[1181]: IO: new interface(s) found: waking up resolver Aug 30 08:46:04 volumio ntpd[1181]: DNS: dns_probe: 3.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 08:46:04 volumio ntpd[1181]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Aug 30 08:46:04 volumio ntpd[1181]: DNS: Pool taking: 162.159.200.1 Aug 30 08:46:04 volumio ntpd[1181]: DNS: Pool taking: 134.60.1.30 Aug 30 08:46:04 volumio ntpd[1181]: DNS: Pool taking: 5.75.181.179 Aug 30 08:46:04 volumio ntpd[1181]: DNS: Pool taking: 91.229.245.70 Aug 30 08:46:04 volumio ntpd[1181]: DNS: dns_take_status: 3.debian.pool.ntp.org=>good, 8 Aug 30 08:46:04 volumio systemd[1]: Started smbd.service - Samba SMB Daemon. Aug 30 08:46:04 volumio systemd[1]: Reached target multi-user.target - Multi-User System. Aug 30 08:46:04 volumio systemd[1]: Reached target graphical.target - Graphical Interface. Aug 30 08:46:04 volumio systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... Aug 30 08:46:04 volumio systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. Aug 30 08:46:04 volumio systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. Aug 30 08:46:04 volumio systemd[1]: Startup finished in 5.970s (firmware) + 3.498s (loader) + 27.140s (kernel) + 17.349s (userspace) = 53.958s. Aug 30 08:46:05 volumio ntpd[1181]: DNS: dns_probe: 2.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 08:46:05 volumio ntpd[1181]: DNS: dns_check: processing 2.debian.pool.ntp.org, 8, 101 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 185.232.69.65 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 178.208.186.228 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 185.168.228.58 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 172.236.195.26 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 2a09:e1c1:efc1:1337::123 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 2a01:4f8:1c0c:40c6:646f:6362:726f:776e Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 2a01:4f8:150:60c3::2 Aug 30 08:46:05 volumio ntpd[1181]: DNS: Pool taking: 2a01:4f8:251:1bce::2 Aug 30 08:46:05 volumio ntpd[1181]: DNS: dns_take_status: 2.debian.pool.ntp.org=>good, 8 Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "network"... Aug 30 08:46:05 volumio volumio[1334]: info: Refreshing Cached IP Addresses Aug 30 08:46:05 volumio sudo[1661]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 08:46:05 volumio sudo[1661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:46:05 volumio sudo[1663]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 08:46:05 volumio sudo[1663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:46:05 volumio sudo[1661]: pam_unix(sudo:session): session closed for user root Aug 30 08:46:05 volumio sudo[1663]: pam_unix(sudo:session): session closed for user root Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "services"... Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "volumio5onboarding"... Aug 30 08:46:05 volumio sudo[1676]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 30 08:46:05 volumio sudo[1676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "alsa_controller"... Aug 30 08:46:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "wizard"... Aug 30 08:46:05 volumio volumio[1334]: info: Loading plugin "networkfs"... Aug 30 08:46:05 volumio sudo[1676]: pam_unix(sudo:session): session closed for user root Aug 30 08:46:06 volumio volumio[1334]: info: Starting Udev Watcher for removable devices Aug 30 08:46:06 volumio volumio[1334]: info: Ignoring mount for partition: boot Aug 30 08:46:06 volumio volumio[1334]: info: Ignoring mount for partition: volumio Aug 30 08:46:06 volumio volumio[1334]: info: Ignoring mount for partition: volumio_data Aug 30 08:46:06 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 08:46:06 volumio volumio[1334]: info: Loading plugin "volumio_command_line_client"... Aug 30 08:46:06 volumio ntpd[1181]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 08:46:06 volumio volumio[1334]: info: Loading plugin "upnp"... Aug 30 08:46:06 volumio ntpd[1181]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Aug 30 08:46:06 volumio ntpd[1181]: DNS: Pool taking: 212.18.3.18 Aug 30 08:46:06 volumio ntpd[1181]: DNS: Pool taking: 62.113.219.231 Aug 30 08:46:06 volumio ntpd[1181]: DNS: Pool taking: 162.19.170.154 Aug 30 08:46:06 volumio ntpd[1181]: DNS: Pool taking: 144.76.76.107 Aug 30 08:46:06 volumio ntpd[1181]: DNS: dns_take_status: 1.debian.pool.ntp.org=>good, 8 Aug 30 08:46:06 volumio volumio[1334]: info: [1788072366252] Starting Upmpd Daemon Aug 30 08:46:06 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 08:46:06 volumio volumio[1334]: info: Loading plugin "my_music"... Aug 30 08:46:06 volumio volumio[1334]: info: Loading plugin "mpd"... Aug 30 08:46:06 volumio volumio-remote-updater[893]: [2026-08-30 08:46:06] [connect] Successful connection Aug 30 08:46:07 volumio ntpd[1181]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Aug 30 08:46:07 volumio ntpd[1181]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Aug 30 08:46:07 volumio ntpd[1181]: DNS: Pool taking: 212.132.108.186 Aug 30 08:46:07 volumio ntpd[1181]: DNS: Pool taking: 79.133.44.138 Aug 30 08:46:07 volumio ntpd[1181]: DNS: Pool taking: 141.144.246.224 Aug 30 08:46:07 volumio ntpd[1181]: DNS: Pool taking: 81.3.27.46 Aug 30 08:46:07 volumio ntpd[1181]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Aug 30 08:46:07 volumio volumio[1334]: info: Loading plugin "upnp_browser"... Aug 30 08:46:08 volumio volumio[1334]: info: Starting UPNP Browser Aug 30 08:46:08 volumio volumio[1334]: info: Loading plugin "alarm-clock"... Aug 30 08:46:08 volumio volumio[1334]: info: Loading plugin "airplay_emulation"... Aug 30 08:46:08 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:46:08 volumio volumio[1334]: info: Loading plugin "last_100"... Aug 30 08:46:08 volumio volumio[1334]: info: Loading plugin "webradio"... Aug 30 08:46:09 volumio volumio[1334]: info: Loading plugin "i2s_dacs"... Aug 30 08:46:09 volumio volumio[1334]: info: I2S DAC not set, start Auto-detection Aug 30 08:46:09 volumio volumio[1334]: info: Loading plugin "volumiodiscovery"... Aug 30 08:46:09 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 1. Aug 30 08:46:09 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:46:09 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:46:09 volumio upmpdcli[1735]: Could not open config: /tmp/upmpdcli.conf Aug 30 08:46:09 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:46:09 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 08:46:09 volumio node[1334]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** For more information see Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 08:46:09 volumio volumio[1334]: *** WARNING *** For more information see Aug 30 08:46:09 volumio node[1334]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 08:46:09 volumio node[1334]: *** WARNING *** For more information see Aug 30 08:46:09 volumio node[1334]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 30 08:46:09 volumio node[1334]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 30 08:46:09 volumio node[1334]: *** WARNING *** For more information see Aug 30 08:46:09 volumio volumio[1334]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 30 08:46:09 volumio volumio[1334]: info: Discovery: Started advertising with name: Volumio Aug 30 08:46:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 30 08:46:09 volumio volumio[1334]: info: Loading plugin "spop"... Aug 30 08:46:47 volumio ntpd[1181]: CLOCK: time stepped by 37.272577 Aug 30 08:46:47 volumio ntpd[1181]: INIT: MRU 10922 entries, 13 hash bits, 65536 bytes Aug 30 08:46:55 volumio volumio[1334]: info: Loading plugin "outputs"... Aug 30 08:46:55 volumio volumio[1334]: info: Loading plugin "albumart"... Aug 30 08:46:55 volumio volumio[1334]: info: Plugin example_plugin is not enabled Aug 30 08:46:55 volumio volumio[1334]: info: Loading plugin "inputs"... Aug 30 08:46:55 volumio volumio[1804]: Forking 3 albumart workers Aug 30 08:46:55 volumio volumio[1334]: info: Loading plugin "updater_comm"... Aug 30 08:46:55 volumio volumio[1815]: Starting albumart workers Aug 30 08:46:55 volumio volumio[1814]: Starting albumart workers Aug 30 08:46:55 volumio volumio[1816]: Starting albumart workers Aug 30 08:46:55 volumio volumio[1334]: info: Plugin mpdemulation is not enabled Aug 30 08:46:55 volumio volumio[1334]: info: Loading plugin "rest_api"... Aug 30 08:46:56 volumio volumio[1334]: info: Loading plugin "websocket"... Aug 30 08:46:56 volumio volumio[1334]: info: Starting Socket.io Server version 1.7.4 Aug 30 08:46:56 volumio volumio[1334]: info: Loading plugin "fusiondsp"... Aug 30 08:46:57 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 30 08:46:58 volumio volumio-remote-updater[893]: [2026-08-30 08:46:58] [connect] Successful connection Aug 30 08:46:58 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 30 08:46:59 volumio volumio[1334]: info: Applying required configuration parameters for plugin fusiondsp Aug 30 08:47:00 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 30 08:47:00 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 30 08:47:00 volumio volumio[1334]: info: Loading plugin "radio_paradise"... Aug 30 08:47:01 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 30 08:47:01 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:47:01 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:47:02 volumio upmpdcli[1969]: Could not open config: /tmp/upmpdcli.conf Aug 30 08:47:02 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:02 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Aug 30 08:47:02 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 30 08:47:02 volumio volumio[1334]: info: Applying required configuration parameters for plugin radio_paradise Aug 30 08:47:02 volumio volumio[1334]: info: [1788072422424] [RadioParadise] API delay: 5 Aug 30 08:47:02 volumio volumio[1334]: info: Loading i18n strings for locale de Aug 30 08:47:02 volumio volumio[1334]: Updating browse sources language Aug 30 08:47:02 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::initPlayerControls Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: Express server listening on port 3000 Aug 30 08:47:03 volumio volumio[1334]: [Metrics] WebUI: 25s 184.90ms Aug 30 08:47:03 volumio volumio[1334]: info: Setting Device type: x86 Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::resetVolumioState Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::getcurrentVolume Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:03 volumio sudo[1989]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 30 08:47:03 volumio sudo[1989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio volumio[1334]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Aug 30 08:47:03 volumio volumio[1334]: info: Completed loading Core Plugins Aug 30 08:47:03 volumio sudo[1991]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 30 08:47:03 volumio volumio[1334]: info: Preparing to generate the ALSA configuration file Aug 30 08:47:03 volumio sudo[1991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio sudo[1989]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio sudo[1991]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio volumio[1334]: info: Volumio Network Manager: Network status updated: 1 Aug 30 08:47:03 volumio volumio[1334]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Aug 30 08:47:03 volumio volumio[1334]: info: VolumeController:: Volume=100 Mute =false Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::updateTrackBlock Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrackBlock Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioRetrievevolume Aug 30 08:47:03 volumio volumio[1334]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 30 08:47:03 volumio volumio[1334]: info: Reading ALSA contributions from plugins. Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::setRepeat null single undefined Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::setRandom null Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:03 volumio volumio[1334]: info: Reloading queue from file Aug 30 08:47:03 volumio volumio-remote-updater[893]: [2026-08-30 08:47:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788072418 101 Aug 30 08:47:03 volumio sudo[2005]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 30 08:47:03 volumio sudo[2005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio volumio[1334]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Aug 30 08:47:03 volumio volumio[1334]: info: VolumeController:: Volume=100 Mute =false Aug 30 08:47:03 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:03 volumio volumio[1334]: info: Discovery: adding 4a5907fa-10b5-4ab7-93a4-81feada78a5b Aug 30 08:47:03 volumio volumio[1334]: info: Discovery: Found device Volumio Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: Discovery: this is already registered, 4a5907fa-10b5-4ab7-93a4-81feada78a5b Aug 30 08:47:03 volumio volumio[1334]: info: Discovery: Found device Volumio Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:03 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:03 volumio volumio[1334]: info: Asound.conf file written Aug 30 08:47:03 volumio sudo[2011]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 30 08:47:03 volumio sudo[2011]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio sudo[2011]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio volumio[1334]: info: Output device has changed, restarting MPD Aug 30 08:47:03 volumio volumio[1334]: info: Output device has changed, restarting Shairport Sync Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:03 volumio sudo[2017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 08:47:03 volumio sudo[2017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio sudo[2019]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 08:47:03 volumio sudo[2019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio sudo[2017]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio volumio[1334]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 08:47:03 volumio volumio[1334]: info: ___________ START PLUGINS ___________ Aug 30 08:47:03 volumio volumio[1334]: info: ControllerMpd::onStart: Initializing MPD Aug 30 08:47:03 volumio volumio[1334]: info: Creating MPD Configuration file Aug 30 08:47:03 volumio sudo[2027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 30 08:47:03 volumio sudo[2027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 08:47:03 volumio volumio[1334]: info: [1788072423610] CoreMusicLibrary::Adding element Medienserver Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:03 volumio sudo[2030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 08:47:03 volumio sudo[2030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio volumio[1334]: info: UPNP Browser: Client initialized successfully Aug 30 08:47:03 volumio sudo[2030]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:03 volumio sudo[2032]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 08:47:03 volumio sudo[2032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:03 volumio volumio[1334]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 08:47:03 volumio volumio[1334]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 08:47:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 08:47:03 volumio volumio[1334]: info: [1788072423647] CoreMusicLibrary::Adding element Last_100 Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 08:47:03 volumio volumio[1334]: info: [1788072423648] CoreMusicLibrary::Adding element Webradio Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:47:03 volumio volumio[1334]: info: Initializing BBC Radios Aug 30 08:47:03 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 30 08:47:03 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 30 08:47:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 30 08:47:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 30 08:47:03 volumio sudo[2027]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 30 08:47:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 30 08:47:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:47:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: Creating Spotify config file Aug 30 08:47:03 volumio sudo[2060]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 08:47:03 volumio sudo[2060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio sudo[2061]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 08:47:03 volumio sudo[2060]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:03 volumio volumio[1334]: info: FusionDsp - CamillaDSP binary found. Aug 30 08:47:03 volumio volumio[1334]: info: Loading i18n strings for locale de Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:03 volumio volumio[1334]: info: FusionDsp - mixtype--------------------- Hardware Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 08:47:03 volumio volumio[1334]: info: [1788072423972] CoreMusicLibrary::Adding element Radio Paradise Aug 30 08:47:03 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:03 volumio volumio[1334]: Cannot find translation for source Radio Paradise Aug 30 08:47:03 volumio volumio[1334]: info: Volumio Calling Home Aug 30 08:47:04 volumio volumio[1334]: info: Preparing to generate the ALSA configuration file Aug 30 08:47:04 volumio volumio[1334]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 30 08:47:04 volumio volumio[1334]: info: Reading ALSA contributions from plugins. Aug 30 08:47:04 volumio volumio[1334]: info: MPD Permissions set Aug 30 08:47:04 volumio volumio[1334]: info: MPD Permissions set Aug 30 08:47:04 volumio volumio[1334]: info: Spotify config file written Aug 30 08:47:04 volumio volumio[1334]: info: Volumio called home Aug 30 08:47:04 volumio volumio[1334]: info: No need to fix Spotify hosts Aug 30 08:47:04 volumio volumio[1334]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 30 08:47:04 volumio volumio[1334]: info: Asound.conf file unchanged, so no further update is needed Aug 30 08:47:04 volumio volumio[1334]: info: Output device has changed, restarting MPD Aug 30 08:47:04 volumio volumio[1334]: info: Output device has changed, restarting Shairport Sync Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:04 volumio sudo[2078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 30 08:47:04 volumio sudo[2078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio sudo[2087]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 08:47:04 volumio sudo[2085]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 08:47:04 volumio sudo[2085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio sudo[2087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio sudo[2085]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 08:47:04 volumio volumio[1334]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 30 08:47: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. Aug 30 08:47: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. Aug 30 08:47:04 volumio volumio[1334]: info: MPD Permissions set Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:04 volumio sudo[2078]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 30 08:47:04 volumio go-librespot[2095]: go-librespot daemon starting... Aug 30 08:47:04 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 30 08:47:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 30 08:47:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 30 08:47:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 30 08:47:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 30 08:47:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 08:47:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio sudo[2107]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 08:47:04 volumio sudo[2107]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 08:47:04 volumio sudo[2116]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Aug 30 08:47:04 volumio sudo[2107]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:04 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:47:04 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:47:04 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:47:04 volumio sudo[2128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 08:47:04 volumio sudo[2128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:47:04 volumio sudo[2131]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 08:47:04 volumio sudo[2129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 08:47:04 volumio sudo[2129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio sudo[2131]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:04.616+02:00 level=INFO msg="running volumio5-device-gateway" version=6370e0a8+CHANGES buildDate=2026-03-06T16:29:42Z Aug 30 08:47:04 volumio sudo[2134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 08:47:04 volumio sudo[2134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:04 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 08:47:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 08:47:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 08:47:04 volumio systemd[1]: shairport-sync.service: Consumed 1.983s CPU time. Aug 30 08:47:04 volumio volumio[1334]: 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 Aug 30 08:47:04 volumio volumio[1334]: 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 Aug 30 08:47:04 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:04 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:04 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:04 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:04.672+02:00 level=INFO msg="system info for baa96382a4d4c251d5213436a36cad26" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.119 Aug 30 08:47:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 08:47:04 volumio sudo[2128]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: info: Shairport-Sync Started Aug 30 08:47:04 volumio sudo[2134]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: Error adding Membership: Error: addMembership EINVAL Aug 30 08:47:04 volumio sudo[2129]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio sudo[2131]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:04 volumio volumio[1334]: info: Shairport-Sync Started Aug 30 08:47:04 volumio volumio[1334]: info: Shairport-Sync Started Aug 30 08:47:04 volumio volumio[1334]: info: Shairport-Sync Started Aug 30 08:47:04 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:04.700+02:00 level=INFO msg="bootstrapping state" hasInternet=true Aug 30 08:47:04 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:04 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:04 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:04 volumio volumio-remote-updater[893]: Test mode disabled Aug 30 08:47:04 volumio volumio-remote-updater[893]: Alpha mode disabled Aug 30 08:47:04 volumio volumio-remote-updater[893]: Alpha legacy test mode disabled Aug 30 08:47:04 volumio volumio[1334]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 30 08:47:04 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 08:47:05 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:05 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:05 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 30 08:47:05 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 30 08:47:05 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:05.244+02:00 level=INFO msg="enabling local network discovery" Aug 30 08:47:05 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:05.275+02:00 level=INFO msg="enabling BLE discovery" Aug 30 08:47:05 volumio go-librespot[2104]: time="2026-08-30T08:47:05+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:05 volumio go-librespot[2104]: time="2026-08-30T08:47:05+02:00" level=debug msg="app state loaded" Aug 30 08:47:05 volumio go-librespot[2104]: time="2026-08-30T08:47:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:06 volumio volumio[1334]: info: camilladsp service started and running in background, instance 1 Aug 30 08:47:06 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 176400 192000 384000 768000 <-AAAAAAAAAAAAA Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp loaded Aug 30 08:47:06 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp - Reporting Fusion DSP Enabled Aug 30 08:47:06 volumio volumio[1334]: info: Adding Signal Path Element [object Object] Aug 30 08:47:06 volumio volumio[1334]: info: Adding fusiondspeq DSP Signal Path Element Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp - ---- installed callbackRead Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 30 08:47:06 volumio volumio[1334]: info: FusionDsp - Effects disabled Aug 30 08:47:06 volumio sudo[2185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Aug 30 08:47:06 volumio sudo[2185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:06 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47: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-gew1.spotify.com:80]" Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+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]" Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+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]" Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=info msg="zeroconf server listening on port 34093" Aug 30 08:47:06 volumio volumio5-onboarding[2049]: time=2026-08-30T08:47:06.249+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=debug msg="obtained new client token: AAFKwK9PtwacZqb61bPyaHXHaSwnfCJAuWfyBPri/QKN6IKF4RgUQDH8FQBe51mBSUQDoorpQBCw5zpgGO0n3t1vHT6bXceDQSNwJ4uVuze49/wrk+xt9OZUmgbSTxNrlGl5Gg3cp2L6U+M/rIsI1mWSRUijTtjTqATaJSlto2FZfp0fhfdlkRAHr9XiYpZaYe4bsi8BTgMsQVLeXasioQo3wb91947sTUkWPx+i/ZR9VXBsbHpAAjDITjc=" Aug 30 08:47:06 volumio volumio[1334]: error: FusionDsp - Reload WebSocket error: [object Object] Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:06 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 30 08:47:06 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=debug msg="completed challenge" Aug 30 08:47:06 volumio systemd[1]: Started fusiondsp.service - FusionDsp Daemon. Aug 30 08:47:06 volumio sudo[2185]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:06 volumio go-librespot[2104]: time="2026-08-30T08:47:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:07 volumio volumio[1334]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Aug 30 08:47:07 volumio volumio[1334]: info: go-librespot daemon successfully initialized Aug 30 08:47:07 volumio volumio[1334]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::volumioGetVisibleSources Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:08 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 30 08:47:08 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:08 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:08 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:08 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:08 volumio volumio[1334]: info: Listing playlists Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 08:47:08 volumio volumio[1334]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 30 08:47:08 volumio volumio[1334]: error: FusionDsp - failed to read local file: Error: ENOENT: no such file or directory, scandir '/data/INTERNAL/FusionDsp/presets//EQ3' Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:09 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 30 08:47:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:09 volumio go-librespot[2196]: go-librespot daemon starting... Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=debug msg="app state loaded" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+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]" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+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]" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+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]" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=info msg="zeroconf server listening on port 46483" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=debug msg="obtained new client token: AAHDdoJv34+lt2rO6QeLlWTFxa3E2p/sCkKOmKAaeQ+lSIO1sj1PF5Dxn1hK7vJMLehNwsOZ6f2/tuyVTbyzo+DWgMnPkY++2Lw1vg1wppM0cKFp8ctB8j/Vn+BsHHLJCSa0j4xDzQRLO5+sOVyDid43LXO0qBr0Zi2MOrfGcDJ+0GbfJyhWjM1obXCLAhIiGReFPt9L9c3Dtym5yHvMNPwa8UcGTZ0q8xQxBqAQzk8Cr3ZvKZGZ7pOhS2s=" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=debug msg="completed challenge" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:09 volumio go-librespot[2197]: time="2026-08-30T08:47:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 08:47:09 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:09 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:09 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:09 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 30 08:47:10 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Aug 30 08:47:10 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:10 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:11 volumio mpd[2117]: 2026-08-30T08:47:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 30 08:47:11 volumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 30 08:47:11 volumio sudo[2087]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:11 volumio sudo[2019]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:11 volumio sudo[2032]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:11 volumio volumio[1334]: info: Completed starting Core Plugins Aug 30 08:47:11 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:47:11 volumio volumio[1334]: info: ----- MyVolumio plugins startup ---- Aug 30 08:47:11 volumio volumio[1334]: info: ------------------------------------------- Aug 30 08:47:11 volumio volumio[1334]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 30 08:47:11 volumio volumio[1334]: error: MPD error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: error: MPD error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: info: MPD running with PID2117 Aug 30 08:47:11 volumio volumio[1334]: ,establishing connection Aug 30 08:47:11 volumio volumio[1334]: error: MPD error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: error: The expression evaluated to a falsy value: Aug 30 08:47:11 volumio volumio[1334]: assert.ok(self.idling) Aug 30 08:47:11 volumio volumio[1334]: error: updateQueue error: null Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 30 08:47:11 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:11 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:11 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:11 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Aug 30 08:47:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 30 08:47:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:13 volumio go-librespot[2229]: go-librespot daemon starting... Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=debug msg="app state loaded" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+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]" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+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]" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+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]" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=info msg="zeroconf server listening on port 46347" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=debug msg="obtained new client token: AAFiTvAM30gXs/zHnr4DcjWvWKflbxrIamqYZoze5e7YW4BHXH14nhlH24bzFLfLkh65/DJLOIbdhF6nGI1NmtFZucmIkLsORHYvFQuJKkPgkBN/ACEyxZOGb9lxNdvRYy+m4uybM3Znc2tWw5FatqPbieD7KKUp3cEglPRZ48SPQkan/GsdU+PWuM2lmj2J9sYGK+l+d+IGwrSnc89Gj4QdZsqq+CGNvqHo01rIBDeYI20El2q57d5u" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=debug msg="completed challenge" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:13 volumio go-librespot[2230]: time="2026-08-30T08:47:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:13 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:13 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 30 08:47:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:16 volumio volumio[1334]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 30 08:47:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:16 volumio go-librespot[2242]: go-librespot daemon starting... Aug 30 08:47:16 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:16 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=debug msg="app state loaded" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+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]" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+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]" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+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]" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=info msg="zeroconf server listening on port 34101" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=debug msg="obtained new client token: AAGasvZ6aJUQADnSlk3ogWTMtz/2kLOUpqEC80fzO7o2yyMJiWkWYQrAPR8dkZ9lGx7EH7Bz6MDLt0R/hLiq5aOQ1F1C97iyZ40pOcRDNkj30emODdDopi/9xtlDuAXjW8liv1Vf9Gpl5wbVS/RSpZoZXOSfjqyJyvhNlq/mztxjBLTKVryS/Zo+5EyQGq46wWblLMWUKZZV8x7RRE1NST+yJTucX5XF1Ba3gm5XwaWzgyqTfgf0nXat+9Y=" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+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" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=debug msg="completed challenge" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:16 volumio go-librespot[2243]: time="2026-08-30T08:47:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:17 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 3. Aug 30 08:47:17 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:47:17 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 30 08:47:17 volumio sudo[2005]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:17 volumio volumio[1334]: info: Upmpdcli Daemon Started Aug 30 08:47:17 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 30 08:47:19 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:19 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin bluetooth to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin multiroom to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin metavolumio to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin cd_controller to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 30 08:47:19 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 30 08:47:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 30 08:47:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:19 volumio go-librespot[2270]: go-librespot daemon starting... Aug 30 08:47:19 volumio go-librespot[2271]: time="2026-08-30T08:47:19+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:19 volumio go-librespot[2271]: time="2026-08-30T08:47:19+02:00" level=debug msg="app state loaded" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:19+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+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]" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+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]" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=info msg="zeroconf server listening on port 36057" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=debug msg="obtained new client token: AAEJusjgQQ/xB52oWmIXvSYANuHRIHTV8f2FhX4x/YylJNWxBG9zILZNRmKPNG5lPraMy4UNUMG5vqUTQwMpCNP5htvszO7U7o/T4f4nFqcxE+ktgR5kTXRxAYUSVOBNT82Vlo0ikD+8/TiL/uujDW5tL7PfhagTrL/bVZ0c2Jk2AaBccQuXzOEfdK1Uu8wpK2dWEaYdKpr8ra3meXBiVzvJ9sl8T7Xt6uHZ2TCfLjXi1uo4tod2+Xjm" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=debug msg="completed challenge" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:20 volumio go-librespot[2271]: time="2026-08-30T08:47:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 30 08:47:20 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:20 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:20 volumio volumio[1334]: info: Starting MyVolumio Remote Streaming Endpoints Aug 30 08:47:20 volumio volumio[1334]: info: MyVolumio login type: Token Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 30 08:47:20 volumio volumio[1334]: info: Streaming services startup Aug 30 08:47:20 volumio volumio[1334]: info: Starting Streaming Daemon Aug 30 08:47:20 volumio sudo[2280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 08:47:20 volumio sudo[2280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:20 volumio volumio[1334]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 30 08:47:20 volumio sudo[2280]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:20 volumio volumio[1334]: error: Cannot start Volumio Streaming Daemon Aug 30 08:47:20 volumio volumio[1334]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 30 08:47:20 volumio volumio[1334]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 30 08:47:21 volumio volumio[1334]: error: MyVolumio Custom Token format not valid, refreshing it Aug 30 08:47:21 volumio volumio[1334]: info: MyVolumio login type: Token Aug 30 08:47:21 volumio volumio[1334]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 30 08:47:22 volumio upmpdcli[2291]: writing RSA key Aug 30 08:47:22 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:22 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:22 volumio volumio[1334]: info: MyVolumio token set successfully Aug 30 08:47:22 volumio volumio[1334]: info: MYVOLUMIO: Adding device Aug 30 08:47:22 volumio volumio[1334]: info: MYVOLUMIO: Evaluating Server Aug 30 08:47:22 volumio volumio[1334]: info: MyVolumio Plan changed: premium Aug 30 08:47:22 volumio volumio[1334]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Aug 30 08:47:22 volumio volumio[1334]: info: Removing browser output: myVolumio user plan is not superstar Aug 30 08:47:22 volumio volumio[1334]: info: Removing audio output: Aug 30 08:47:22 volumio volumio[1334]: info: MYVOLUMIO: Adding device Aug 30 08:47:22 volumio volumio[1334]: info: MYVOLUMIO: Evaluating Server Aug 30 08:47:22 volumio volumio[1334]: info: Remote config written successfully Aug 30 08:47:22 volumio volumio[1334]: info: Starting Tunnel 1 Aug 30 08:47:22 volumio volumio[1334]: info: Starting Tunnel Connection Checker Aug 30 08:47:22 volumio volumio[1334]: info: Completed starting MyVolumio Plugin Aug 30 08:47:22 volumio volumio[1334]: info: MYVolumio Device enabled Aug 30 08:47:22 volumio volumio[1334]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Aug 30 08:47:22 volumio volumio[1334]: info: MyVolumio status changed Aug 30 08:47:22 volumio volumio[1334]: info: Streaming services startup Aug 30 08:47:22 volumio volumio[1334]: info: Starting Streaming Daemon Aug 30 08:47:22 volumio sudo[2348]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 30 08:47:22 volumio sudo[2348]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:22 volumio sudo[2348]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:22 volumio volumio[1334]: error: Cannot start Volumio Streaming Daemon Aug 30 08:47:22 volumio volumio[1334]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 30 08:47:22 volumio volumio[1334]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 30 08:47:22 volumio volumio[1334]: info: Setting Geolocation for MyVolumio to eu6 Aug 30 08:47:22 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:22 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:22 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:22 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 30 08:47:22 volumio volumio[1334]: error: [MyVolumio PluginManager] Cache data is invalid! Aug 30 08:47:23 volumio volumio[1334]: info: Setting Geolocation for MyVolumio to eu7 Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 30 08:47:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:23 volumio go-librespot[2351]: go-librespot daemon starting... Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=debug msg="app state loaded" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:23 volumio volumio[1334]: info: Successfully Added MyVolumio device Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+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]" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+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]" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=info msg="zeroconf server listening on port 38759" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=debug msg="obtained new client token: AAFsDhn9WZQlFO2e7B+k0DmVUdRTqlZze5OfpLaPFKrFBw5202BxWIBLLe8yxP53HRxjPkjBQuaGThp+jW4oQwKc7f8DLMJBNIKniE0TXK5tExS3K9NxyO295EMxJVKn47Jyk8qWk6A9I5VM+Xl63MXio0cfr14ELWxmiWFkNXv8l8CMxXhOJVBl1/HQ5nGFHAKcDaN7/6WIt7ZJjK8FnwluUwWdIjrYALlVDtfEc0aF+0xCfLHqS3d7JTo=" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=debug msg="completed challenge" Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:23 volumio volumio[1334]: info: Successfully Added MyVolumio device Aug 30 08:47:23 volumio go-librespot[2352]: time="2026-08-30T08:47:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:23 volumio volumio[1334]: info: Updating MyVolumio device info Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:23 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin bluetooth Aug 30 08:47:24 volumio volumio[1334]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Aug 30 08:47:24 volumio sudo[2362]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Aug 30 08:47:24 volumio sudo[2362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:24 volumio sudo[2362]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:24 volumio volumio[1334]: info: MRS: MultiRoom plugin initialized Aug 30 08:47:24 volumio volumio[1334]: info: MRS: STOPPING SNAPCLIENT Aug 30 08:47:24 volumio volumio[1334]: info: MRS: Snap server stop Aug 30 08:47:24 volumio volumio[1334]: info: MRS: STOPPING volumioStreaming Aug 30 08:47:24 volumio sudo[2379]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Aug 30 08:47:24 volumio sudo[2379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:24 volumio sudo[2381]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Aug 30 08:47:24 volumio sudo[2381]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Aug 30 08:47:24 volumio sudo[2385]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Aug 30 08:47:24 volumio sudo[2385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:24 volumio sudo[2386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Aug 30 08:47:24 volumio sudo[2386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:24 volumio sudo[2386]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:24 volumio sudo[2379]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:24 volumio sudo[2381]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Aug 30 08:47:24 volumio sudo[2385]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:24 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Aug 30 08:47:25 volumio volumio[1334]: info: Preparing to generate the ALSA configuration file Aug 30 08:47:25 volumio volumio[1334]: info: Updating MyVolumio device info Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Aug 30 08:47:25 volumio volumio[1334]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 30 08:47:25 volumio volumio[1334]: info: Successfully Updated MyVolumio device Aug 30 08:47:25 volumio volumio[1334]: info: MRS: Removed streaming files Aug 30 08:47:25 volumio volumio[1334]: info: MRS: volumioStreaming STOPPED Aug 30 08:47:25 volumio volumio[1334]: info: MRS: SNAPSERVER STOPPED Aug 30 08:47:25 volumio volumio[1334]: info: MRS: SNAPCLIENT STOPPED Aug 30 08:47:25 volumio volumio[1334]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 30 08:47:25 volumio volumio[1334]: info: Reading ALSA contributions from plugins. Aug 30 08:47:25 volumio volumio[1334]: info: Asound.conf file written Aug 30 08:47:25 volumio sudo[2393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 30 08:47:25 volumio sudo[2393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio sudo[2393]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio volumio[1334]: info: Output device has changed, restarting MPD Aug 30 08:47:25 volumio volumio[1334]: info: Output device has changed, restarting Shairport Sync Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio sudo[2399]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 30 08:47:25 volumio sudo[2399]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio sudo[2399]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio sudo[2403]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 30 08:47:25 volumio sudo[2403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumio[1334]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 30 08:47:25 volumio volumio[1334]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: [FUNC] onStart Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Aug 30 08:47:25 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Aug 30 08:47:25 volumio volumio[1334]: info: MRS: Pushing multiroomSync output for this device Aug 30 08:47:25 volumio volumio[1334]: info: MRS: Pushing multiroomSync output Aug 30 08:47:25 volumio volumio[1334]: info: Adding audio output: Aug 30 08:47:25 volumio volumio[1334]: info: Adding audio output: Aug 30 08:47:25 volumio volumio[1334]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Aug 30 08:47:25 volumio volumio[1334]: info: Adding METAVOLUMIO REST API Endpoints Aug 30 08:47:25 volumio volumio[1334]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Aug 30 08:47:25 volumio volumio[1334]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Aug 30 08:47:25 volumio volumio[1334]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Aug 30 08:47:25 volumio volumio[1334]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Aug 30 08:47:25 volumio volumio[1334]: info: Preparing CD Folders Aug 30 08:47:25 volumio volumio[1334]: info: Adding CD REST API Endpoints Aug 30 08:47:25 volumio volumio[1334]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Aug 30 08:47:25 volumio volumio[1334]: info: Starting UDEV Watcher for CD Aug 30 08:47:25 volumio volumio[1334]: info: Detecting CD presence with UDEV Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Aug 30 08:47:25 volumio bluetoothd[885]: Path / reserved for Adv Monitor app :1.22 Aug 30 08:47:25 volumio bluetoothd[885]: Adv Monitor app :1.22 disconnected from D-Bus Aug 30 08:47:25 volumio systemd[1]: mpd.service: Deactivated successfully. Aug 30 08:47:25 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 30 08:47:25 volumio systemd[1]: mpd.service: Consumed 1.498s CPU time. Aug 30 08:47:25 volumio systemd[1]: mpd.socket: Deactivated successfully. Aug 30 08:47:25 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 30 08:47:25 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 30 08:47:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 30 08:47:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Aug 30 08:47:25 volumio volumio[1334]: info: [cd-plugin] Set CD speed to 1X Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Aug 30 08:47:25 volumio volumio[1334]: info: Adding inputs REST Endpoints Aug 30 08:47:25 volumio volumio[1334]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Aug 30 08:47:25 volumio volumio[1334]: info: Scanning Audio Inputs Aug 30 08:47:25 volumio volumio[1334]: info: Checking against Known Cards name Aug 30 08:47:25 volumio volumio[1334]: info: Checking against Known Cards name Aug 30 08:47:25 volumio volumio[1334]: info: Adding Server instance for streaming Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Aug 30 08:47:25 volumio volumio[1334]: error: Hi Res Audio Failed Login: Missing Login Data Aug 30 08:47:25 volumio volumio[1334]: info: Adding HIGHRESAUDIO REST API Endpoints Aug 30 08:47:25 volumio volumio[1334]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Aug 30 08:47:25 volumio volumio[1334]: info: Refreshing TIDAL token Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Aug 30 08:47:25 volumio sudo[2419]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 30 08:47:25 volumio sudo[2419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 30 08:47:25 volumio volumio[1334]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Aug 30 08:47:25 volumio volumio[1334]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Aug 30 08:47:25 volumio sudo[2419]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio sudo[2425]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 30 08:47:25 volumio sudo[2425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: QobuzConnect: Starting Qobuz Connect socket and service Aug 30 08:47:25 volumio volumio[1334]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Aug 30 08:47:25 volumio volumio[1334]: info: Stopping AccessToken refresher cron for QOBUZ Aug 30 08:47:25 volumio sudo[2433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 30 08:47:25 volumio sudo[2433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumio[1334]: info: AccessToken refresher cron started for QOBUZ Aug 30 08:47:25 volumio volumio[1334]: info: Adding QOBUZ REST API Endpoints Aug 30 08:47:25 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:25 volumio sudo[2433]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio volumio[1334]: info: Successfully Updated MyVolumio device Aug 30 08:47:25 volumio sudo[2425]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio sudo[2435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 30 08:47:25 volumio sudo[2435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Aug 30 08:47:25 volumio volumio[1334]: info: MPD Permissions set Aug 30 08:47:25 volumio sudo[2439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 30 08:47:25 volumio sudo[2439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:25 volumio systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 30 08:47:25 volumio sudo[2435]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 30 08:47:25 volumio sudo[2439]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio volumio[1334]: info: Starting Shairport Sync Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Aug 30 08:47:25 volumio volumio[1334]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Aug 30 08:47:25 volumio sudo[2453]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 30 08:47:25 volumio sudo[2453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio volumiobt[2454]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 30 08:47:25 volumio sudo[2456]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 30 08:47:25 volumio sudo[2456]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio sudo[2456]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 30 08:47:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Aug 30 08:47:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 08:47:25 volumio systemd[1]: shairport-sync.service: Consumed 1.633s CPU time. Aug 30 08:47:25 volumio sudo[2458]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 30 08:47:25 volumio sudo[2458]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:25 volumio sudo[2458]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio volumiobt[2461]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 30 08:47:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 30 08:47:25 volumio bluetoothd[885]: Path / reserved for Adv Monitor app :1.23 Aug 30 08:47:25 volumio bluetoothd[885]: Adv Monitor app :1.23 disconnected from D-Bus Aug 30 08:47:25 volumio sudo[2453]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:25 volumio volumio[1334]: info: Shairport-Sync Started Aug 30 08:47:25 volumio volumiobt[2464]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 30 08:47:25 volumio volumio[1334]: info: Executing endpoint qc_getconfig Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.834 [2442.2442] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 30 08:47:25 volumio volumio[1334]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 30 08:47:25 volumio volumio[1334]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 30 08:47:25 volumio volumiobt[2465]: [176B blob data] Aug 30 08:47:25 volumio volumiobt[2465]: [157B blob data] Aug 30 08:47:25 volumio volumiobt[2465]: [157B blob data] Aug 30 08:47:25 volumio volumiobt[2465]: [157B blob data] Aug 30 08:47:25 volumio volumiobt[2465]: [113B blob data] Aug 30 08:47:25 volumio volumiobt[2465]: [bluetoothctl]> discoverable on Aug 30 08:47:25 volumio volumiobt[2465]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Aug 30 08:47:25 volumio volumiobt[2465]: [bluetoothctl]> pairable on Aug 30 08:47:25 volumio bluetoothd[885]: Path / reserved for Adv Monitor app :1.26 Aug 30 08:47:25 volumio bluetoothd[885]: Adv Monitor app :1.26 disconnected from D-Bus Aug 30 08:47:25 volumio volumiobt[2465]: [bluetoothctl]> Aug 30 08:47:25 volumio volumiobt[2483]: INFO [BTSTART] Registering Bluetooth agent... Aug 30 08:47:25 volumio volumiobt[2484]: [NEW] Media /org/bluez/hci0 Aug 30 08:47:25 volumio volumiobt[2484]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio volumiobt[2484]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio volumiobt[2484]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio bluetoothd[885]: Path / reserved for Adv Monitor app :1.27 Aug 30 08:47:25 volumio bluetoothd[885]: Adv Monitor app :1.27 disconnected from D-Bus Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.892 [2442.2442] INFO VolumeManager: [0x55dc9def4b10]: Setting new playback volume: 75 Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.892 [2442.2442] INFO VolumeManager: [0x55dc9def4b10]: Setting new mute state: 0 Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.892 [2442.2442] INFO AudioStreamManager: [0x55dc9def4670]: Setting new audio download buffer size: 1048576 Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.893 [2442.2442] INFO QobuzConnect: [0x55dc9def5b20]: Client initialized! Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.893 [2442.2442] INFO SampleApp: Starting Avahi advertising, name: Volumio, service name: _qobuz-connect._tcp Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.901 [2442.2442] INFO LocalConfigManager: [0x55dc9def4150]: Starting Local Configuration server Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.901 [2442.2442] INFO SampleApp: Starting Local configuration server Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.901 [2442.2442] INFO SampleApp: Connected to UNIX socket client 0x55dc9decabb0 Aug 30 08:47:25 volumio volumiobt[2485]: No agent is registered Aug 30 08:47:25 volumio volumiobt[2485]: [NEW] Media /org/bluez/hci0 Aug 30 08:47:25 volumio volumiobt[2485]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio volumiobt[2485]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio volumiobt[2485]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 30 08:47:25 volumio bluetoothd[885]: Path / reserved for Adv Monitor app :1.28 Aug 30 08:47:25 volumio bluetoothd[885]: Adv Monitor app :1.28 disconnected from D-Bus Aug 30 08:47:25 volumio volumiobt[2488]: INFO [BTSTART] Agent registered successfully. Aug 30 08:47:25 volumio volumiobt[2489]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 08:47:25 volumio volumio[1334]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 30 08:47:25 volumio volumio[1334]: info: Received Get System Version Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:47:25 volumio volumio[1334]: info: Received Get System Info Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 30 08:47:25 volumio volumio[1334]: info: Discovery: Getting this device information Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:25 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 30 08:47:25 volumio qobuz-connect[2442]: 20260830 08:47:25.983 [2442.2442] INFO SampleApp: Playback volume changed: 75 Aug 30 08:47:25 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:25 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Connecting to system D-Bus Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Connected to system D-Bus Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 bluezutils [INFO] Found adapter at: /org/bluez/hci0 Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Found Bluetooth adapter: /org/bluez/hci0 Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Set DiscoverableTimeout to infinite Aug 30 08:47:26 volumio mpd[2428]: 2026-08-30T08:47:26 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 30 08:47:26 volumio systemd[1]: Started mpd.service - Music Player Daemon. Aug 30 08:47:26 volumio sudo[2403]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Enabled Discoverable mode Aug 30 08:47:26 volumio volumio[1334]: error: updateQueue error: null Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Agent registered at /local/a2dpagent Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] Agent set as default Aug 30 08:47:26 volumio volumiobt[2490]: 2026-08-30 08:47:26 a2dp-agent [INFO] A2DP agent running, waiting for connections... Aug 30 08:47:26 volumio volumio[1334]: info: Access Token successfully retrieved Aug 30 08:47:26 volumio volumio[1334]: info: Successfully retrieved User Session From TIDAL Aug 30 08:47:26 volumio volumio[1334]: info: Successfully retrieved User Subscription From TIDAL Aug 30 08:47:26 volumio volumio[1334]: info: Adding TIDAL to Browse Sources Aug 30 08:47:26 volumio volumio[1334]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 30 08:47:26 volumio volumio[1334]: info: [1788072446644] CoreMusicLibrary::Adding element TIDAL Aug 30 08:47:26 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 30 08:47:26 volumio volumio[1334]: Cannot find translation for source Radio Paradise Aug 30 08:47:26 volumio volumio[1334]: Cannot find translation for source TIDAL Aug 30 08:47:26 volumio volumio[1334]: info: Adding TIDAL REST API Endpoints Aug 30 08:47:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 30 08:47:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:26 volumio go-librespot[2494]: go-librespot daemon starting... Aug 30 08:47:26 volumio go-librespot[2495]: time="2026-08-30T08:47:26+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:26 volumio go-librespot[2495]: time="2026-08-30T08:47:26+02:00" level=debug msg="app state loaded" Aug 30 08:47:26 volumio go-librespot[2495]: time="2026-08-30T08:47:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+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]" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+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]" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+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]" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=info msg="zeroconf server listening on port 40327" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=debug msg="obtained new client token: AAG9xo7L2TncL4aFsx203WF+Y1gzSZ02+fBCtq6V134cPFIGWhdMHTGYIWYSptotiqv6C55TBhwySNme70k/vIes+cO543RsMdI3FZeBv3uFdL/vq9eMXoVVIoX4xIsxUznuu/sxej9XnJas9106G/qOaEWVh7PdGzlPW1WM4TaoVDUQthN57j0tMQN8drpcI4Orc8fkxL303C8ocbBgzqZj4ff+CSRFyLtOJ0dqcIdtoxruSh++9r5X" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+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" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=debug msg="completed challenge" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:27 volumio go-librespot[2495]: time="2026-08-30T08:47:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:27 volumio sudo[2509]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 30 08:47:27 volumio sudo[2509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:27 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 30 08:47:27 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 30 08:47:27 volumio systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 30 08:47:27 volumio sudo[2509]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:27 volumio volumio[1334]: info: Remote SSH Started Aug 30 08:47:27 volumio autossh[2512]: port set to 0, monitoring disabled Aug 30 08:47:27 volumio autossh[2512]: starting ssh (count 1) Aug 30 08:47:27 volumio autossh[2512]: ssh child pid is 2515 Aug 30 08:47:27 volumio volumio[1334]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 30 08:47:27 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:27 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumiossh-tunnel[2515]: Warning: Permanently added '[eu7.myvolumio.org]:2222' (RSA) to the list of known hosts. Aug 30 08:47:28 volumio volumio[1334]: info: TidalConnect service stoped! Aug 30 08:47:28 volumio volumio[1334]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 30 08:47:28 volumio volumio[1334]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 30 08:47:28 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:28 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:28 volumio sudo[2526]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 30 08:47:28 volumio sudo[2526]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 30 08:47:28 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Aug 30 08:47:28 volumio sudo[2526]: pam_unix(sudo:session): session closed for user root Aug 30 08:47:28 volumio volumio[1334]: info: Executing endpoint tc_getconfig Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 30 08:47:28 volumio vtcs[2529]: STARTING TidalConnect services, version: 1.6.1 Aug 30 08:47:28 volumio vtcs[2529]: STARTED TidalConnect services. Aug 30 08:47:28 volumio volumio[1334]: info: Executing endpoint tc_connect Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 30 08:47:28 volumio volumio[1334]: info: Connecting to TidalConnect Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::servicePushState Aug 30 08:47:28 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:28 volumio volumio[1334]: info: MRS: Pushing multiroomSync output update for this device Aug 30 08:47:28 volumio volumio[1334]: info: MRS: Pushing multiroomSync output Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::servicePushState Aug 30 08:47:28 volumio volumio[1334]: info: CoreStateMachine::pushState Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::volumioPushState Aug 30 08:47:28 volumio volumio[1334]: info: MRS: Pushing multiroomSync output update for this device Aug 30 08:47:28 volumio volumio[1334]: info: MRS: Pushing multiroomSync output Aug 30 08:47:28 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:28 volumio volumio[1334]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Aug 30 08:47:28 volumio volumio[1334]: info: FusionDsp - Volumio is not playing Aug 30 08:47:28 volumio volumio[1334]: info: FusionDsp - Clipped samples monitor stopped Aug 30 08:47:28 volumio volumio[1334]: info: FusionDsp - Volumio is not playing Aug 30 08:47:28 volumio volumio[1334]: info: FusionDsp - Clipped samples monitor stopped Aug 30 08:47:30 volumio volumio[1334]: info: MRS: Getting audio outputs on start Aug 30 08:47:30 volumio volumio[1334]: info: MRS: Requesting all other devices output Aug 30 08:47:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 30 08:47:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:30 volumio go-librespot[2547]: go-librespot daemon starting... Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=debug msg="app state loaded" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+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]" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+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]" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+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]" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=info msg="zeroconf server listening on port 41409" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=debug msg="obtained new client token: AAHqy9FIy2jxjerMDdcd8j40jgrbSDCdRTH8MklPfzW29TT0GFeJH7wsWRt0uNQCoGHKk6vAUu79CF4Z5yV4xec/0KMOnp5c7k/2qohmU/BWqNffEHu5ZTUfLuVF2uVt7ZTZmQCUcApKDuYxZGlexGQ6yavgQZNOkdvP0S4Php6ueb1CdBrB1lZdzEjX311Fr6mYlqLlfvhfM/ciJYPJl52QCydyMYrawXdrGqaFBLo9Uw9RsPLb1qe4Tys=" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=debug msg="completed challenge" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:30 volumio go-librespot[2548]: time="2026-08-30T08:47:30+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:31 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:31 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:31 volumio volumio[1334]: info: TidalConnect service started! Aug 30 08:47:31 volumio volumio[1334]: [Metrics] CommandRouter: 52s 958.88ms Aug 30 08:47:31 volumio volumio[1334]: info: CoreCommandRouter::volumiosetStartupVolume Aug 30 08:47:31 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:31 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:31 volumio volumio[1334]: info: CoreCommandRouter::Close All Modals sent Aug 30 08:47:31 volumio volumio[1334]: info: CoreCommandRouter::Close All Modals sent Aug 30 08:47:31 volumio volumio[1334]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 30 08:47:31 volumio volumio[1334]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 30 08:47:31 volumio volumio[1334]: info: camilladsp stopping service pid 2180... Aug 30 08:47:31 volumio volumio[1334]: grep: /proc/2180/cmdline: binary file matches Aug 30 08:47:31 volumio volumio[1334]: info: camilladsp service terminated, instance 1 Aug 30 08:47:31 volumio volumio[1334]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 30 08:47:31 volumio volumio[1334]: info: FusionDsp - Effects disabled Aug 30 08:47:31 volumio volumio[1334]: info: camilladsp service started and running in background, instance 1 Aug 30 08:47:32 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 30 08:47:32 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 30 08:47:32 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 30 08:47:33 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:47:33 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 30 08:47:33 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 30 08:47:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 30 08:47:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:34 volumio go-librespot[2599]: go-librespot daemon starting... Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=debug msg="app state loaded" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:34 volumio volumio-remote-updater[893]: Test mode disabled Aug 30 08:47:34 volumio volumio-remote-updater[893]: Alpha mode disabled Aug 30 08:47:34 volumio volumio-remote-updater[893]: Alpha legacy test mode disabled Aug 30 08:47:34 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 30 08:47:34 volumio volumio[1334]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 30 08:47:34 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+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]" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+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]" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+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]" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=info msg="zeroconf server listening on port 38919" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=debug msg="obtained new client token: AAEB4kRbc8OWRnD6rUK5w4lzRG56xckZY348vmdAyhsD33ANj7taKCSIga+sCtLRUV7LYGXbvj/PcnqpCPRyr90TtKfxp7MgsI6b2DrpfaVVg/IKhWzsSNNJYhrXBWFdMvmd5LSI7dB233UIEsjl8jOOCuF3CDGhmKvFdH2Lwk5kDVOFAN659kyK77AM2FYKFOHH/AduI4SchTQwfyJ7P6pcxk7ahfzIvbdHsMhlNSgbyNEKheoxFhqV" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=debug msg="completed challenge" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:34 volumio go-librespot[2600]: time="2026-08-30T08:47:34+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:34 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:34 volumio volumio[1334]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:35 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 30 08:47:35 volumio volumio[1334]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 30 08:47:35 volumio volumio[1334]: info: CoreCommandRouter::volumioGetState Aug 30 08:47:35 volumio volumio[1334]: info: CorePlayQueue::getTrack 0 Aug 30 08:47:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 30 08:47:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 30 08:47:37 volumio go-librespot[2615]: go-librespot daemon starting... Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=info msg="running go-librespot 0.4.0" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="app state loaded" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=info msg="zeroconf server listening on port 33351" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="obtained new client token: AAFCuwE1pzSbXmgs0RV63qpNQc/rMpPo2V5ps9yD5/Uwt7pEdEYyKE1R6Rc9huZB6JUTRN3UuT2Q9D5z7BeJFvRrnMLliTobh793oHmpbMyPJUclyy/Q2JfY0aFvVWaiicHMu3bAlpGwvpJU5gN6KG/amSgQMXb7lHMD34XFdUYgwLSAamxKI+JQUcT662Lqunl5mCaujKxea0OF1mSfWbFMGBQ4lrgld3c84dhtYlSo9+9wEXgyh9wBYhw=" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="completed keyexchange" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="completed challenge" Aug 30 08:47:37 volumio volumio[1334]: info: Initializing connection to go-librespot Websocket Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=debug msg="new websocket client" Aug 30 08:47:37 volumio volumio[1334]: info: Connection to go-librespot Websocket established Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=info msg="authenticated AP" username="tu*********************p4" Aug 30 08:47:37 volumio go-librespot[2616]: time="2026-08-30T08:47:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 30 08:47:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 30 08:47:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 30 08:47:37 volumio volumio[1334]: info: Connection to go-librespot Websocket closed Aug 30 08:47:38 volumio volumio[1334]: info: BOOT COMPLETED Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::volumioGetBrowseSources Aug 30 08:47:40 volumio volumio[1334]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 30 08:47:40 volumio volumio[1334]: info: Getting Spotify volume Aug 30 08:47:40 volumio volumio[1334]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 08:47:40 volumio volumio[1334]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 30 08:47:40 volumio volumio[1334]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 30 08:47:40 volumio volumio[1334]: errno: -111, Aug 30 08:47:40 volumio volumio[1334]: code: 'ECONNREFUSED', Aug 30 08:47:40 volumio volumio[1334]: syscall: 'connect', Aug 30 08:47:40 volumio volumio[1334]: address: '127.0.0.1', Aug 30 08:47:40 volumio volumio[1334]: port: 9879, Aug 30 08:47:40 volumio volumio[1334]: response: undefined Aug 30 08:47:40 volumio volumio[1334]: } Aug 30 08:47:40 volumio volumio[1334]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 30 08:47:40 volumio sudo[2641]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-30 08:46' Aug 30 08:47:40 volumio sudo[2641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"