Jan 08 12:43:00 volumio volumio[26178]: info: Spotify config file written Jan 08 12:43:00 volumio sudo[26590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 12:43:00 volumio sudo[26590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:00 volumio volumio[26178]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jan 08 12:43:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:00 volumio volumio[26178]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:43:00 volumio volumio[26178]: info: CoreStateMachine::pushState Jan 08 12:43:00 volumio volumio[26178]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Server discovery started Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Player finder started Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 08 12:43:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio go-librespot[26592]: go-librespot daemon starting... Jan 08 12:43:00 volumio sudo[26590]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="app state loaded" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:00 volumio volumio[26178]: info: No need to fix Spotify hosts Jan 08 12:43:00 volumio volumio[26178]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 08 12:43:00 volumio volumio[26178]: info: Volumio called home Jan 08 12:43:00 volumio volumio[26178]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:43:00 volumio volumio[26178]: SPOTIFY: BQBpaCjRiQywqO1K3xF6I-mNfnhnpztloqC787GdR8vnE6xApWpr0tmTw-pK6XFOBSQL5QTI8c6Xdk7-HnnL0jRLJySmbCdvdRBVpvd65hIHm9bFIWO0eBm21uDOCU7cFaezJU6HDN9re2Gv3nd2TZ3LZY-3oXmtArL5exhni-qaY8O93KPxxICW9lwAKomVr1GmuJiRO7LhElq4ULTI1Wy_BCm8Jrlspq9Od6A Jan 08 12:43:00 volumio volumio[26178]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:43:00 volumio volumio[26178]: info: New Spotify access token = BQBpaCjRiQywqO1K3xF6I-mNfnhnpztloqC787GdR8vnE6xApWpr0tmTw-pK6XFOBSQL5QTI8c6Xdk7-HnnL0jRLJySmbCdvdRBVpvd65hIHm9bFIWO0eBm21uDOCU7cFaezJU6HDN9re2Gv3nd2TZ3LZY-3oXmtArL5exhni-qaY8O93KPxxICW9lwAKomVr1GmuJiRO7LhElq4ULTI1Wy_BCm8Jrlspq9Od6A Jan 08 12:43:00 volumio volumio[26178]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=info msg="zeroconf server listening on port 38373" Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 08 12:43:00 volumio volumio[26178]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:43:00 volumio volumio[26178]: info: Starting Shairport Sync Jan 08 12:43:00 volumio volumio[26178]: info: Starting Shairport Sync Jan 08 12:43:00 volumio go-librespot[26595]: time="2026-01-08T12:43:00-06:00" level=debug msg="obtained new client token: AACo3UMxJwNyagbobor11+N30lNAFsExnJgmT18USuVY+AMhwnFJfp6V98sPjrwXbMj2RSCyB7VZLKBdoOs17InqgJHFZaKi3nTrFagZY7LAo7qM45kkj6eWxqV9W3/gR7fei7NQ3AS+ZUQTEHpHLZj5eJDxPuxlTOt13mBTn1PgwgtCKiL53Vt6h/X0a7eelMWdoe4VAMnyEkDOTUKIeWziFZuKMDYsP4pbmW6Pez2ercaat9V6e0jacQ==" Jan 08 12:43:01 volumio volumio[26178]: info: Starting Shairport Sync Jan 08 12:43:01 volumio sudo[26620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:01 volumio sudo[26618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:01 volumio sudo[26620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio sudo[26618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio sudo[26616]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:01 volumio sudo[26616]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio go-librespot[26595]: time="2026-01-08T12:43:01-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 08 12:43:01 volumio go-librespot[26595]: time="2026-01-08T12:43:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 08 12:43:01 volumio sudo[26614]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:43:01 volumio sudo[26614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio sudo[26614]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio go-librespot[26595]: time="2026-01-08T12:43:01-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:01 volumio go-librespot[26595]: time="2026-01-08T12:43:01-06:00" level=debug msg="completed challenge" Jan 08 12:43:01 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:43:01 volumio go-librespot[26595]: time="2026-01-08T12:43:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:01 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:43:01 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:01 volumio systemd[1]: shairport-sync.service: Consumed 1.921s CPU time. Jan 08 12:43:01 volumio volumio[26178]: info: Asound.conf file unchanged, so no further update is needed Jan 08 12:43:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:01 volumio volumio[26178]: info: Output device has changed, restarting MPD Jan 08 12:43:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:01 volumio volumio[26178]: info: Output device has changed, restarting Shairport Sync Jan 08 12:43:01 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:01 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:01 volumio sudo[26628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:43:01 volumio sudo[26628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:01 volumio sudo[26620]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio sudo[26630]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:43:01 volumio sudo[26628]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio sudo[26630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio sudo[26618]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.185.238 Jan 08 12:43:01 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:01 volumio avahi-daemon[664]: Registering new address record for 169.254.185.238 on eth0.IPv4. Jan 08 12:43:01 volumio sudo[26616]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio volumio[26178]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:43:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.185.238 Jan 08 12:43:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:01 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:43:01 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:43:01 volumio systemd[1]: mpd.service: Consumed 2.932s CPU time. Jan 08 12:43:01 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:43:01 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:43:01 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:43:01 volumio volumio[26178]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 08 12:43:01 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:43:01 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:43:01 volumio sudo[26674]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 08 12:43:01 volumio sudo[26674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:01 volumio sudo[26674]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.185.238 Jan 08 12:43:01 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.185.238 Jan 08 12:43:01 volumio avahi-daemon[664]: Withdrawing address record for 169.254.185.238 on eth0. Jan 08 12:43:01 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:01 volumio volumio[26178]: info: MPD Permissions set Jan 08 12:43:01 volumio volumio[26178]: info: Shairport-Sync Started Jan 08 12:43:01 volumio volumio[26178]: Error adding Membership: Error: addMembership EINVAL Jan 08 12:43:01 volumio volumio[26178]: info: Shairport-Sync Started Jan 08 12:43:01 volumio volumio[26178]: info: Shairport-Sync Started Jan 08 12:43:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:02 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:02 volumio volumio[26178]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:02 volumio sudo[26675]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 12:43:02 volumio sudo[26675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::volumioGetState Jan 08 12:43:02 volumio sudo[26675]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:02 volumio sudo[26695]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:43:02 volumio sudo[26695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:02 volumio volumio[26178]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:02 volumio sudo[26695]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:02 volumio volumio[26178]: info: Starting Shairport Sync Jan 08 12:43:02 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 08 12:43:02 volumio sudo[26705]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:02 volumio sudo[26705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:02 volumio volumio[26178]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 08 12:43:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:43:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:43:02 volumio volumio[26178]: info: Spotify Successfully logged in Jan 08 12:43:02 volumio sudo[26708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 08 12:43:02 volumio sudo[26708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:02 volumio sudo[26705]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:02 volumio volumio[26178]: info: [1767897782329] CoreMusicLibrary::Adding element Spotify Jan 08 12:43:02 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source SoundCloud Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source YouTube2 Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source YouTube Music Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source Podcast Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source Volusonic Jan 08 12:43:02 volumio volumio[26178]: Cannot find translation for source Spotify Jan 08 12:43:02 volumio systemd[1]: Reloading. Jan 08 12:43:02 volumio volumio[26178]: info: Shairport-Sync Started Jan 08 12:43:03 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:03 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:03 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:03 volumio volumio[26178]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:03 volumio volumio[26178]: info: go-librespot daemon successfully initialized Jan 08 12:43:05 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. Jan 08 12:43:05 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. Jan 08 12:43:05 volumio sudo[26708]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 08 12:43:05 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:05 volumio sudo[26743]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:05 volumio sudo[26743]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:05 volumio go-librespot[26744]: go-librespot daemon starting... Jan 08 12:43:05 volumio go-librespot[26746]: time="2026-01-08T12:43:05-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:05 volumio go-librespot[26746]: time="2026-01-08T12:43:05-06:00" level=debug msg="app state loaded" Jan 08 12:43:05 volumio go-librespot[26746]: time="2026-01-08T12:43:05-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:05 volumio go-librespot[26746]: time="2026-01-08T12:43:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:05 volumio sudo[26743]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:05 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 08 12:43:05 volumio sudo[26753]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 08 12:43:05 volumio sudo[26753]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:05 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:06 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 08 12:43:06 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=info msg="zeroconf server listening on port 39137" Jan 08 12:43:06 volumio sudo[26753]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="obtained new client token: AAAcOvWgZokAnd9bJSqlGWHhI5EEUj2n+sf594p8orAdU0NSYyB9Ho4Qm4B5DhKpibOWzroE6IAVWfaYAKbEmlTKlutKmZkqV0UIWXBQjseV7x2r5Ntq0axCnPZuv7Ecut3acwB0LE+1R3+jgIxYPoseSVfRgOyDRVBwX1cuFfAc83PEyQ3D/AxWxmohKFL4TF6YBc6Bw1Jc/zbT+Gt1gP4e8DVD5ZCwU02bBbXP2e5HO3uxy2zSxZ0=" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=debug msg="completed challenge" Jan 08 12:43:06 volumio go-librespot[26746]: time="2026-01-08T12:43:06-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:06 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:06 volumio sudo[26760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:06 volumio sudo[26760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:06 volumio sudo[26760]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:06 volumio volumio[26178]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 08 12:43:06 volumio sudo[26764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 08 12:43:06 volumio sudo[26764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:06 volumio sudo[26764]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:06 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 08 12:43:06 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.211.226 Jan 08 12:43:06 volumio avahi-daemon[664]: Registering new address record for 169.254.211.226 on eth0.IPv4. Jan 08 12:43:06 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:06 volumio sudo[26767]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 08 12:43:06 volumio sudo[26767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:06 volumio volumio[26178]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:06 volumio volumio[26178]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 12:43:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.211.226 Jan 08 12:43:07 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 08 12:43:07 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 08 12:43:07 volumio sudo[26767]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:07 volumio mpd[26703]: 2026-01-08T12:43:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 12:43:07 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 12:43:07 volumio sudo[26630]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:07 volumio sudo[26539]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:07 volumio sudo[26523]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.211.226 Jan 08 12:43:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.211.226 Jan 08 12:43:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.211.226 on eth0. Jan 08 12:43:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:07 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:07 volumio volumio[26178]: error: MPD error: The expression evaluated to a falsy value: Jan 08 12:43:07 volumio volumio[26178]: assert.ok(self.idling) Jan 08 12:43:07 volumio volumio[26178]: error: The expression evaluated to a falsy value: Jan 08 12:43:07 volumio volumio[26178]: assert.ok(self.idling) Jan 08 12:43:07 volumio volumio[26178]: error: MPD error: The expression evaluated to a falsy value: Jan 08 12:43:07 volumio volumio[26178]: assert.ok(self.idling) Jan 08 12:43:07 volumio volumio[26178]: error: The expression evaluated to a falsy value: Jan 08 12:43:07 volumio volumio[26178]: assert.ok(self.idling) Jan 08 12:43:07 volumio volumio[26178]: error: updateQueue error: null Jan 08 12:43:07 volumio volumio[26178]: info: MPD running with PID26703 Jan 08 12:43:07 volumio volumio[26178]: ,establishing connection Jan 08 12:43:07 volumio volumio[26178]: error: updateQueue error: null Jan 08 12:43:07 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:07 volumio sudo[26811]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:07 volumio sudo[26811]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:07 volumio sudo[26811]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:07 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:43:07 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:07] [connect] Successful connection Jan 08 12:43:07 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:07] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767897787 101 Jan 08 12:43:07 volumio volumio[26178]: 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: 3 Jan 08 12:43:08 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:08 volumio sudo[26815]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:08 volumio sudo[26815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:08 volumio sudo[26815]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:08 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:08 volumio sudo[26818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:08 volumio sudo[26818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:08 volumio sudo[26818]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:09 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:09 volumio sudo[26821]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:09 volumio sudo[26821]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jan 08 12:43:09 volumio sudo[26821]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:09 volumio go-librespot[26823]: go-librespot daemon starting... Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="app state loaded" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=info msg="zeroconf server listening on port 34861" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="obtained new client token: AAAgbWEXPWTIPvN0QUV/Gc+if9v8xwzTac+Q1vL9RZnMEP+sSBqx+zXcONhNPlCDM1u1oBRuY1BEaWNx/7EiUrkYKMA1v3Q63P6Gez4nggjvc/LnlKj8tE0+gaVhDNdpWim8H/SUd7PrvOEC+sqLvrZQc4bdrFi/KxC7ZAziYZSIlfOtVDpA3RP3SIrfuP2HZRHMab2ImYDEScz2QieVIa4+rRzE8gaVV7IHLDGnI5FKYRAHGERBzYQDnA==" Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:09 volumio volumio[26178]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:09 volumio go-librespot[26824]: time="2026-01-08T12:43:09-06:00" level=debug msg="new websocket client" Jan 08 12:43:09 volumio volumio[26178]: info: Connection to go-librespot Websocket established Jan 08 12:43:09 volumio volumio[26178]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:09 volumio sudo[26832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:10 volumio go-librespot[26824]: time="2026-01-08T12:43:10-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:10 volumio sudo[26832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:10 volumio go-librespot[26824]: time="2026-01-08T12:43:10-06:00" level=debug msg="completed challenge" Jan 08 12:43:10 volumio go-librespot[26824]: time="2026-01-08T12:43:10-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:10 volumio sudo[26832]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:10 volumio volumio[26178]: info: Connection to go-librespot Websocket closed Jan 08 12:43:10 volumio volumio[26178]: info: Completed starting Core Plugins Jan 08 12:43:10 volumio volumio[26178]: info: ------------------------------------------- Jan 08 12:43:10 volumio volumio[26178]: info: ----- MyVolumio plugins startup ---- Jan 08 12:43:10 volumio volumio[26178]: info: ------------------------------------------- Jan 08 12:43:10 volumio volumio[26178]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 12:43:10 volumio sudo[26849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:10 volumio sudo[26849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:10 volumio sudo[26851]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:10 volumio sudo[26851]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:10 volumio sudo[26853]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:10 volumio sudo[26853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:10 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 12:43:10 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 12:43:10 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 12:43:10 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 12:43:10 volumio sudo[26849]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:10 volumio mpd_monitor.sh[26857]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 12:43:10 volumio sudo[26851]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:10 volumio sudo[26853]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:10 volumio volumio[26178]: info: Successfully started MPD Monitor Jan 08 12:43:10 volumio volumio[26178]: info: Successfully started MPD Monitor Jan 08 12:43:10 volumio volumio[26178]: info: Successfully started MPD Monitor Jan 08 12:43:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.17.13 Jan 08 12:43:12 volumio avahi-daemon[664]: Registering new address record for 169.254.17.13 on eth0.IPv4. Jan 08 12:43:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:12 volumio volumio[26178]: info: Getting Spotify volume Jan 08 12:43:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.13 Jan 08 12:43:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.13 Jan 08 12:43:13 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.17.13 Jan 08 12:43:13 volumio avahi-daemon[664]: Withdrawing address record for 169.254.17.13 on eth0. Jan 08 12:43:13 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 08 12:43:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:13 volumio volumio[26178]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:43:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:13 volumio volumio[26178]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 12:43:13 volumio volumio[26178]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 08 12:43:13 volumio volumio[26178]: errno: -111, Jan 08 12:43:13 volumio volumio[26178]: code: 'ECONNREFUSED', Jan 08 12:43:13 volumio volumio[26178]: syscall: 'connect', Jan 08 12:43:13 volumio volumio[26178]: address: '127.0.0.1', Jan 08 12:43:13 volumio volumio[26178]: port: 9879, Jan 08 12:43:13 volumio volumio[26178]: response: undefined Jan 08 12:43:13 volumio volumio[26178]: } Jan 08 12:43:13 volumio volumio[26178]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:43:13 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:13 volumio go-librespot[26890]: go-librespot daemon starting... Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="app state loaded" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=info msg="zeroconf server listening on port 42795" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="obtained new client token: AADIAjjFQpkh0H17H17z0NufHzYu7dqhraRq3uo4Z9T/bVrmdsKogcJzGDmmTagmH+/rYqTEdIzoyu8GnTh39nsuM1PBuk3yMthO68hvpzZTNF6hq9qBRXSy2J1YiS59YC6BiDPIEtw8kHkX9XRgqxYiC/4fDK3q+vbrf6bD6jxYDvJqoD6sLOVhjmwY4qRWYznz6p4dUQxSxC2+PjI97Mttn7hIT6fGyn3yILTqkVOf8LMPDVvgDuy+ZA==" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=debug msg="completed challenge" Jan 08 12:43:13 volumio go-librespot[26906]: time="2026-01-08T12:43:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:13 volumio sudo[26916]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 12:42' Jan 08 12:43:13 volumio sudo[26916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:14 volumio sudo[26916]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:14 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:14] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 08 12:43:14 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:14] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 08 12:43:14 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:14 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 08 12:43:14 volumio systemd[1]: volumio.service: Consumed 48.429s CPU time. Jan 08 12:43:14 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 12:43:14 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 12:43:14 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 14880. Jan 08 12:43:14 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 12:43:14 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 08 12:43:14 volumio systemd[1]: volumio.service: Consumed 48.429s CPU time. Jan 08 12:43:14 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 08 12:43:14 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 12:43:16 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:16 volumio volumio[26928]: info: ----- Volumio3 ---- Jan 08 12:43:16 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:16 volumio volumio[26928]: info: ----- System startup ---- Jan 08 12:43:16 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Jan 08 12:43:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:16 volumio go-librespot[26949]: go-librespot daemon starting... Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="app state loaded" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:17 volumio volumio[26928]: info: MYVOLUMIO Environment detected Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=info msg="zeroconf server listening on port 38365" Jan 08 12:43:17 volumio volumio[26928]: info: Plugin folders cleanup Jan 08 12:43:17 volumio volumio[26928]: info: Scanning into folder /volumio/app/plugins/ Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category audio_interface Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category miscellanea Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category music_service Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category plugins.json Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category system_controller Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category user_interface Jan 08 12:43:17 volumio volumio[26928]: info: Scanning into folder /data/plugins/ Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category audio_interface Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category music_service Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category system_controller Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category system_hardware Jan 08 12:43:17 volumio volumio[26928]: info: Scanning category user_interface Jan 08 12:43:17 volumio volumio[26928]: info: Plugin folders cleanup completed Jan 08 12:43:17 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:17 volumio volumio[26928]: info: ----- Core plugins startup ---- Jan 08 12:43:17 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:17 volumio volumio[26928]: info: Loading plugins from folder /volumio/app/plugins/ Jan 08 12:43:17 volumio volumio[26928]: info: Adding plugin upnp to MyMusic Plugins Jan 08 12:43:17 volumio volumio[26928]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 08 12:43:17 volumio volumio[26928]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 08 12:43:17 volumio volumio[26928]: info: Loading plugins from folder /data/plugins/ Jan 08 12:43:17 volumio volumio[26928]: info: Loading plugin "system"... Jan 08 12:43:17 volumio volumio[26928]: info: Loading plugin "appearance"... Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="obtained new client token: AABDR7U6ktkMZmg0LJgsCNBpiXUQjBDashYHk4RSUTsUJfz5uqR/VC40YJ2+Dk5k5+x/YcLUvtpWGxnhHXw3ffOCbf+GByFrIzvUaD64o+brzCz2JhGgCMj3vbvVrJyGcQD3n6PcI0hN5Kt+xI+gUkOL2mM/IfFGpMUQlbJGQ9s9G1orSNx439CR9gD0YAxid7V2EFubM3jd2T22CDtGUQo4W/7a6VIqvdV7dyCWRCD0pwVLeDVqFahmwQ==" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=debug msg="completed challenge" Jan 08 12:43:17 volumio go-librespot[26950]: time="2026-01-08T12:43:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:17 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.152.53 Jan 08 12:43:17 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:17 volumio avahi-daemon[664]: Registering new address record for 169.254.152.53 on eth0.IPv4. Jan 08 12:43:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.152.53 Jan 08 12:43:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.152.53 Jan 08 12:43:18 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.152.53 Jan 08 12:43:18 volumio avahi-daemon[664]: Withdrawing address record for 169.254.152.53 on eth0. Jan 08 12:43:18 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:18 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "network"... Jan 08 12:43:18 volumio volumio[26928]: info: Refreshing Cached IP Addresses Jan 08 12:43:18 volumio sudo[26997]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 12:43:18 volumio sudo[26997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:18 volumio sudo[26999]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 12:43:18 volumio sudo[26999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:18 volumio sudo[26997]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "services"... Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "alsa_controller"... Jan 08 12:43:18 volumio sudo[26999]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:18 volumio sudo[27006]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 08 12:43:18 volumio sudo[27006]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:18 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "wizard"... Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "networkfs"... Jan 08 12:43:18 volumio volumio[26928]: info: Starting Udev Watcher for removable devices Jan 08 12:43:18 volumio volumio[26928]: info: Ignoring mount for partition: boot Jan 08 12:43:18 volumio volumio[26928]: info: Ignoring mount for partition: volumio Jan 08 12:43:18 volumio volumio[26928]: info: Ignoring mount for partition: volumio_data Jan 08 12:43:18 volumio volumio[26928]: info: Mounting Device Wikipedia Jan 08 12:43:18 volumio sudo[27036]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 08 12:43:18 volumio sudo[27036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:18 volumio sudo[27036]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:18 volumio volumio[26928]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 08 12:43:18 volumio volumio[26928]: dmesg(1) may have more information after failed mount system call. Jan 08 12:43:18 volumio volumio[26928]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 08 12:43:18 volumio volumio[26928]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 08 12:43:18 volumio volumio[26928]: dmesg(1) may have more information after failed mount system call. Jan 08 12:43:18 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "volumio_command_line_client"... Jan 08 12:43:18 volumio volumio[26928]: info: Loading plugin "upnp"... Jan 08 12:43:19 volumio volumio[26928]: info: [1767897799006] Starting Upmpd Daemon Jan 08 12:43:19 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:43:19 volumio volumio[26928]: info: Loading plugin "my_music"... Jan 08 12:43:19 volumio volumio[26928]: info: Loading plugin "mpd"... Jan 08 12:43:19 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:19] [connect] Successful connection Jan 08 12:43:19 volumio sudo[27006]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:19 volumio volumio[26928]: info: Loading plugin "upnp_browser"... Jan 08 12:43:20 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:43:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jan 08 12:43:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:20 volumio go-librespot[27039]: go-librespot daemon starting... Jan 08 12:43:20 volumio go-librespot[27040]: time="2026-01-08T12:43:20-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:20 volumio go-librespot[27040]: time="2026-01-08T12:43:20-06:00" level=debug msg="app state loaded" Jan 08 12:43:20 volumio go-librespot[27040]: time="2026-01-08T12:43:20-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:20 volumio go-librespot[27040]: time="2026-01-08T12:43:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:21 volumio go-librespot[27040]: time="2026-01-08T12:43:21-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:21 volumio go-librespot[27040]: time="2026-01-08T12:43:21-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:21 volumio go-librespot[27040]: time="2026-01-08T12:43:21-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:21 volumio go-librespot[27040]: time="2026-01-08T12:43:21-06:00" level=info msg="zeroconf server listening on port 40159" Jan 08 12:43:22 volumio go-librespot[27040]: time="2026-01-08T12:43:22-06:00" level=debug msg="obtained new client token: AACh1pUS0w+uFBVayrLiNENhuKm3RIvTCgQSeqFZ/Yoa+ISMX+/nhrZl4wC+cfjMmCUw+96hxrzMkd6yt4gA7tQ5hloQ9YxFSuKVJlFCUuyQZl/Wwzflv88zIspe44HlD98c5cj3SaxudraLXimIygF5auCWM1Cw5adJRzeqh8R9EqO4jP+bPX6xyNXz1Yk5lzOkpQ0s8wzFB5KM3bR+s4n+bBzyk9B1hzdzArHoVKAK+k10aMdyBTQ=" Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "alarm-clock"... Jan 08 12:43:22 volumio go-librespot[27040]: time="2026-01-08T12:43:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "airplay_emulation"... Jan 08 12:43:22 volumio volumio[26928]: info: Starting Shairport Sync Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "last_100"... Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "webradio"... Jan 08 12:43:22 volumio go-librespot[27040]: time="2026-01-08T12:43:22-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:22 volumio go-librespot[27040]: time="2026-01-08T12:43:22-06:00" level=debug msg="completed challenge" Jan 08 12:43:22 volumio go-librespot[27040]: time="2026-01-08T12:43:22-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "i2s_dacs"... Jan 08 12:43:22 volumio volumio[26928]: info: I2S DAC not set, start Auto-detection Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "volumiodiscovery"... Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** For more information see Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:43:22 volumio volumio[26928]: *** WARNING *** For more information see Jan 08 12:43:22 volumio node[26928]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 12:43:22 volumio node[26928]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:43:22 volumio node[26928]: *** WARNING *** For more information see Jan 08 12:43:22 volumio node[26928]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 12:43:22 volumio node[26928]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:43:22 volumio node[26928]: *** WARNING *** For more information see Jan 08 12:43:22 volumio volumio[26928]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 08 12:43:22 volumio volumio[26928]: info: Discovery: Started advertising with name: Volumio Jan 08 12:43:22 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:43:22 volumio volumio[26928]: info: Loading plugin "bandcamp"... Jan 08 12:43:23 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.107.45 Jan 08 12:43:23 volumio avahi-daemon[664]: Registering new address record for 169.254.107.45 on eth0.IPv4. Jan 08 12:43:23 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.107.45 Jan 08 12:43:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.107.45 Jan 08 12:43:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.107.45 Jan 08 12:43:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.107.45 on eth0. Jan 08 12:43:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:23 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:23 volumio volumio[26928]: info: Plugin calmradio is not enabled Jan 08 12:43:23 volumio volumio[26928]: info: Loading plugin "soundcloud"... Jan 08 12:43:24 volumio volumio[26928]: info: Loading plugin "spop"... Jan 08 12:43:24 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:43:25 volumio volumio[26928]: info: Loading plugin "squeezelite_mc"... Jan 08 12:43:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Jan 08 12:43:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:25 volumio go-librespot[27082]: go-librespot daemon starting... Jan 08 12:43:25 volumio go-librespot[27083]: time="2026-01-08T12:43:25-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:25 volumio go-librespot[27083]: time="2026-01-08T12:43:25-06:00" level=debug msg="app state loaded" Jan 08 12:43:25 volumio go-librespot[27083]: time="2026-01-08T12:43:25-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:25 volumio go-librespot[27083]: time="2026-01-08T12:43:25-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:26 volumio volumio[26928]: info: Loading plugin "youtube2"... Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=info msg="zeroconf server listening on port 35931" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="obtained new client token: AAChB+6bvxYr1YCLKPAEx6mMQEaNbuUCnAnB3VnWXiCaxmcMvEsspeEiCILOCR8Zyu3SJfT6RnQcWFGEwqwMGUQ3W15vRfoY+EztHrL2PP3DS5TJ81E/9+sOHndzqEEEq0t7OftY8SC5KN4IwxyDILTg0Zb5H2FA9Ws3JmDAfJn/HNqrD1UCTzTydSU/cwTEi/g1COaZCNDYn7R4fXf+e8//pnkW6E2dMP7G5I/qGF2V4I5dsSs4glA=" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=debug msg="completed challenge" Jan 08 12:43:26 volumio go-librespot[27083]: time="2026-01-08T12:43:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:26 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:43:26 volumio volumio[26928]: info: Loading plugin "ytcr"... Jan 08 12:43:27 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.33.177 Jan 08 12:43:27 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:27 volumio avahi-daemon[664]: Registering new address record for 169.254.33.177 on eth0.IPv4. Jan 08 12:43:28 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:28 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:28 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:28 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.33.177 Jan 08 12:43:28 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.33.177 Jan 08 12:43:28 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.33.177 Jan 08 12:43:28 volumio avahi-daemon[664]: Withdrawing address record for 169.254.33.177 on eth0. Jan 08 12:43:28 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:28 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:28 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:28 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:28 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:29 volumio volumio[26928]: info: Loading plugin "ytmusic"... Jan 08 12:43:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Jan 08 12:43:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:29 volumio go-librespot[27136]: go-librespot daemon starting... Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=debug msg="app state loaded" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:29 volumio go-librespot[27137]: time="2026-01-08T12:43:29-06:00" level=info msg="zeroconf server listening on port 34913" Jan 08 12:43:30 volumio go-librespot[27137]: time="2026-01-08T12:43:30-06:00" level=debug msg="obtained new client token: AAANTb80GKuzn8QIu9tbP0mvLsptaQ0QwcEYM5xvgX0oX7wdCivNQA9UJu9Uxtj0/gC7TanIzQW1qUI3r/0KHgM7FVZtf+DH7Gq7/EIHkn/3DUMj3a/6cI4wPQ6p6NqDLsDcVufk5k+4oaCJQe7xr8FeYUQYNLsPZYN++kas5/w89iP4lx6f08uiCRCGKhX/Pc1JV9vlgR4Hv5aLE6WXGa/n+vgChh6fbUVbsyq3LYGyCyFnySR/Ypg=" Jan 08 12:43:30 volumio volumio[26928]: info: Plugin now_playing is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "outputs"... Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "albumart"... Jan 08 12:43:30 volumio go-librespot[27137]: time="2026-01-08T12:43:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:30 volumio volumio[26928]: info: Plugin example_plugin is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "inputs"... Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "updater_comm"... Jan 08 12:43:30 volumio go-librespot[27137]: time="2026-01-08T12:43:30-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:30 volumio go-librespot[27137]: time="2026-01-08T12:43:30-06:00" level=debug msg="completed challenge" Jan 08 12:43:30 volumio go-librespot[27137]: time="2026-01-08T12:43:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:30 volumio volumio[26928]: info: Plugin mpdemulation is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "rest_api"... Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "websocket"... Jan 08 12:43:30 volumio volumio[26928]: info: Starting Socket.io Server version 1.7.4 Jan 08 12:43:30 volumio volumio[26928]: info: Plugin fusiondsp is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Plugin mpdoutput is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Plugin RoonBridge is not enabled Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "podcast"... Jan 08 12:43:30 volumio volumio[26928]: info: ControllerPodcast::constructor Jan 08 12:43:30 volumio volumio[26928]: info: Loading plugin "volusonic"... Jan 08 12:43:30 volumio volumio[27144]: Forking 3 albumart workers Jan 08 12:43:31 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:31] [connect] Successful connection Jan 08 12:43:32 volumio volumio[26928]: info: Applying required configuration parameters for plugin volusonic Jan 08 12:43:32 volumio volumio[26928]: info: Loading plugin "backup_restore"... Jan 08 12:43:32 volumio volumio[27158]: Starting albumart workers Jan 08 12:43:32 volumio volumio[27157]: Starting albumart workers Jan 08 12:43:33 volumio volumio[26928]: info: Applying required configuration parameters for plugin backup_restore Jan 08 12:43:33 volumio volumio[26928]: info: Plugin rpi_eeprom_config is not enabled Jan 08 12:43:33 volumio volumio[26928]: info: Plugin rpi_eeprom_updater is not enabled Jan 08 12:43:33 volumio volumio[26928]: info: Loading plugin "scheduledrestart"... Jan 08 12:43:33 volumio volumio[27159]: Starting albumart workers Jan 08 12:43:33 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.90.208 Jan 08 12:43:33 volumio avahi-daemon[664]: Registering new address record for 169.254.90.208 on eth0.IPv4. Jan 08 12:43:33 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:33 volumio volumio[26928]: info: Applying required configuration parameters for plugin scheduledrestart Jan 08 12:43:33 volumio volumio[26928]: info: Plugin Bluetoothremote is not enabled Jan 08 12:43:33 volumio volumio[26928]: info: Plugin music_services_shield is not enabled Jan 08 12:43:33 volumio volumio[26928]: info: Loading plugin "Systeminfo"... Jan 08 12:43:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Jan 08 12:43:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:33 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.208 Jan 08 12:43:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:33 volumio go-librespot[27204]: go-librespot daemon starting... Jan 08 12:43:33 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:33 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:33 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:33 volumio go-librespot[27205]: time="2026-01-08T12:43:33-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:33 volumio go-librespot[27205]: time="2026-01-08T12:43:33-06:00" level=debug msg="app state loaded" Jan 08 12:43:33 volumio go-librespot[27205]: time="2026-01-08T12:43:33-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:33 volumio go-librespot[27205]: time="2026-01-08T12:43:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:33 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.208 Jan 08 12:43:33 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.90.208 Jan 08 12:43:33 volumio avahi-daemon[664]: Withdrawing address record for 169.254.90.208 on eth0. Jan 08 12:43:33 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:33 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:33 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:33 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:33 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=info msg="zeroconf server listening on port 39779" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="obtained new client token: AAAR8YuXIWge2vz1v9BkVztt8wHbsd1wAYupnubZ/ipXzH0sf8ilY8ziGtAwNbNhPTAbjIfi/SAkOl14LQSuZ5qaAQTNoVkkh3vY81xH6G8hyZA5T8SzAJQ1nz3Wmgcv0CKHnmvvs+5j5hzgyCAzrJWt6TGrJG/We3pzC6Ep7mKf7ojotYrauz9+VzNuUzSeJqXXZJvbR0cU5IC1Tbx9G8KDJSdfMnjiZrtge+VT1Cq/iQTMc7YRe/zjTw==" Jan 08 12:43:34 volumio volumio[26928]: info: Plugin peppymeterbasic is not enabled Jan 08 12:43:34 volumio volumio[26928]: info: Loading plugin "peppyspectrum"... Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=debug msg="completed challenge" Jan 08 12:43:34 volumio go-librespot[27205]: time="2026-01-08T12:43:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:34 volumio volumio[26928]: info: Loading i18n strings for locale en Jan 08 12:43:34 volumio volumio[26928]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 08 12:43:34 volumio volumio[26928]: Updating browse sources language Jan 08 12:43:34 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::initPlayerControls Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: Express server listening on port 3000 Jan 08 12:43:35 volumio volumio[26928]: [Metrics] WebUI: 19s 181.82ms Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::resetVolumioState Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::getcurrentVolume Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:35 volumio sudo[27252]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 12:43:35 volumio sudo[27252]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio sudo[27254]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 12:43:35 volumio sudo[27252]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:35 volumio sudo[27254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio sudo[27254]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:35 volumio volumio[26928]: info: Volumio Network Manager: Network status updated: 1 Jan 08 12:43:35 volumio volumio[26928]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::pushState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::updateTrackBlock Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrackBlock Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:43:35 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767897811 101 Jan 08 12:43:35 volumio volumio[26928]: 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 Jan 08 12:43:35 volumio volumio[26928]: info: Reloading queue from file Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::setRepeat null single undefined Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::pushState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::setRandom null Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::pushState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:35 volumio volumio[26928]: info: Setting Device type: Raspberry PI Jan 08 12:43:35 volumio volumio[26928]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:43:35 volumio volumio[26928]: info: CoreStateMachine::pushState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:35 volumio volumio[26928]: info: Completed loading Core Plugins Jan 08 12:43:35 volumio volumio[26928]: info: Preparing to generate the ALSA configuration file Jan 08 12:43:35 volumio sudo[27267]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 12:43:35 volumio sudo[27267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio volumio[26928]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 08 12:43:35 volumio volumio[26928]: info: Discovery: Found device Volumio Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioGetState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio sudo[27267]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:35 volumio volumio[26928]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 08 12:43:35 volumio volumio[26928]: info: Discovery: Found device Volumio Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioGetState Jan 08 12:43:35 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:35 volumio volumio[26928]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 08 12:43:35 volumio volumio[26928]: info: Reading ALSA contributions from plugins. Jan 08 12:43:35 volumio volumio[26928]: info: Upmpdcli Daemon Started Jan 08 12:43:35 volumio volumio[26928]: info: Asound.conf file unchanged, so no further update is needed Jan 08 12:43:35 volumio volumio[26928]: info: Output device has changed, restarting MPD Jan 08 12:43:35 volumio volumio[26928]: info: Output device has changed, restarting Shairport Sync Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:35 volumio sudo[27270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:43:35 volumio sudo[27270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio sudo[27270]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:35 volumio sudo[27272]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:43:35 volumio sudo[27272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio volumio[26928]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:43:35 volumio volumio[26928]: info: ___________ START PLUGINS ___________ Jan 08 12:43:35 volumio volumio[26928]: info: ControllerMpd::onStart: Initializing MPD Jan 08 12:43:35 volumio volumio[26928]: info: Creating MPD Configuration file Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:35 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:35 volumio volumio[26928]: info: [1767897815740] CoreMusicLibrary::Adding element Media Servers Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio sudo[27280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:43:35 volumio sudo[27280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio sudo[27280]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:35 volumio sudo[27282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:43:35 volumio sudo[27282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:35 volumio volumio[26928]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:35 volumio volumio[26928]: info: [1767897815854] CoreMusicLibrary::Adding element Last_100 Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:35 volumio volumio[26928]: info: [1767897815858] CoreMusicLibrary::Adding element Webradio Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:43:35 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:43:35 volumio systemd[1]: mpd.service: Consumed 5.606s CPU time. Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:43:35 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:43:35 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:43:35 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:43:35 volumio volumio[26928]: info: Initializing BBC Radios Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:35 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:35 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:43:35 volumio volumio[26928]: info: [1767897815942] CoreMusicLibrary::Adding element Bandcamp Discover Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:35 volumio volumio[26928]: info: [1767897815960] CoreMusicLibrary::Adding element SoundCloud Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:35 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:35 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:35 volumio volumio[26928]: info: Creating Spotify config file Jan 08 12:43:35 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio sudo[27307]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 12:43:36 volumio sudo[27307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 12:43:36 volumio sudo[27307]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:36 volumio volumio[26928]: info: [squeezelite_mc] Starting proxy server... Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:36 volumio volumio[26928]: info: [1767897816315] CoreMusicLibrary::Adding element YouTube2 Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:36 volumio volumio[26928]: info: [1767897816344] CoreMusicLibrary::Adding element YouTube Music Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:36 volumio volumio[26928]: info: [1767897816355] CoreMusicLibrary::Adding element Podcast Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Podcast Jan 08 12:43:36 volumio volumio[26928]: info: Loading i18n strings for locale en Jan 08 12:43:36 volumio volumio[26928]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 08 12:43:36 volumio volumio[26928]: Updating browse sources language Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Podcast Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Podcast Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:36 volumio volumio[26928]: info: [1767897816403] CoreMusicLibrary::Adding element Volusonic Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Podcast Jan 08 12:43:36 volumio volumio[26928]: Cannot find translation for source Volusonic Jan 08 12:43:36 volumio volumio[26928]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 08 12:43:36 volumio volumio[26928]: info: Volumio Calling Home Jan 08 12:43:36 volumio volumio[26928]: info: [squeezelite_mc] Proxy server started on port 36059 Jan 08 12:43:36 volumio volumio[26928]: info: Preparing to generate the ALSA configuration file Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:43:36 volumio volumio[26928]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 08 12:43:36 volumio volumio[26928]: info: Reading ALSA contributions from plugins. Jan 08 12:43:36 volumio volumio[26928]: info: MPD Permissions set Jan 08 12:43:36 volumio volumio[26928]: info: MPD Permissions set Jan 08 12:43:36 volumio volumio[26928]: info: Spotify config file written Jan 08 12:43:36 volumio sudo[27317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 12:43:36 volumio sudo[27317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:36 volumio volumio[26928]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 08 12:43:36 volumio volumio[26928]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:43:36 volumio volumio[26928]: info: CoreStateMachine::pushState Jan 08 12:43:36 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::volumioPushState Jan 08 12:43:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:36 volumio volumio[26928]: info: [squeezelite_mc] Server discovery started Jan 08 12:43:36 volumio volumio[26928]: info: [squeezelite_mc] Player finder started Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:36 volumio go-librespot[27319]: go-librespot daemon starting... Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio sudo[27317]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:36 volumio volumio[26928]: info: No need to fix Spotify hosts Jan 08 12:43:36 volumio go-librespot[27327]: time="2026-01-08T12:43:36-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:36 volumio go-librespot[27327]: time="2026-01-08T12:43:36-06:00" level=debug msg="app state loaded" Jan 08 12:43:36 volumio go-librespot[27327]: time="2026-01-08T12:43:36-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:36 volumio go-librespot[27327]: time="2026-01-08T12:43:36-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:36 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:43:37 volumio volumio[26928]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 08 12:43:37 volumio volumio[26928]: info: Volumio called home Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=info msg="zeroconf server listening on port 42321" Jan 08 12:43:37 volumio volumio[26928]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 08 12:43:37 volumio volumio[26928]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 08 12:43:37 volumio volumio[26928]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:43:37 volumio volumio[26928]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:43:37 volumio volumio[26928]: SPOTIFY: BQAVk3Xy1jbI3R0lfOqvYzeJGR2ityQkSzNQS-6X390IGF6qPrQTuDhU35Mao36MHXb_TFiLA8xBPFKCgR2V6LTJ55d1rgC3dkaocWdAgoT2mLRbBiXQvhuAU_ekDv1e6AVhkKsOmQRSUS2UARizFfaqaXhATGNj1Jg-cYxTM1FyUrOLNXyVfBZ0yksCx36-TCegeaTEKVIbdA1T_lx1C1IK-YTYoe0nIBCtGF0 Jan 08 12:43:37 volumio volumio[26928]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:43:37 volumio volumio[26928]: info: New Spotify access token = BQAVk3Xy1jbI3R0lfOqvYzeJGR2ityQkSzNQS-6X390IGF6qPrQTuDhU35Mao36MHXb_TFiLA8xBPFKCgR2V6LTJ55d1rgC3dkaocWdAgoT2mLRbBiXQvhuAU_ekDv1e6AVhkKsOmQRSUS2UARizFfaqaXhATGNj1Jg-cYxTM1FyUrOLNXyVfBZ0yksCx36-TCegeaTEKVIbdA1T_lx1C1IK-YTYoe0nIBCtGF0 Jan 08 12:43:37 volumio volumio[26928]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="obtained new client token: AADrD8kozutVzj92bNdyHW52BlTVrrB/YN7Pt0TdmqXWV4WiBHfrEZws/d4kKHNbB9UnEuopRA2hE5WsYCRoSbkpvgwOXHwWqlcUHv8m0i/T9NbvAoqbHjG+sH9lLkQJCCd2F1k5ZOhIrpNh04Go2HtdO+Pg80QC7k6sh2kG8tGE0OWu8UkaDypHRC1a2E7xDRMkjvdt6P/JeB/v5FcSSI6n0BkhjtNbfqJMO5mYSXeQv4iKw3Wm5D8uSw==" Jan 08 12:43:37 volumio volumio[26928]: info: Starting Shairport Sync Jan 08 12:43:37 volumio volumio[26928]: info: Starting Shairport Sync Jan 08 12:43:37 volumio volumio[26928]: info: Starting Shairport Sync Jan 08 12:43:37 volumio sudo[27346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:37 volumio sudo[27346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:37 volumio sudo[27343]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:43:37 volumio sudo[27343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio sudo[27348]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:37 volumio sudo[27348]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio sudo[27351]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:37 volumio sudo[27351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=debug msg="completed challenge" Jan 08 12:43:37 volumio sudo[27343]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:43:37 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:43:37 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:37 volumio systemd[1]: shairport-sync.service: Consumed 1.894s CPU time. Jan 08 12:43:37 volumio go-librespot[27327]: time="2026-01-08T12:43:37-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:37 volumio volumio[26928]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 08 12:43:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:37 volumio sudo[27348]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio sudo[27346]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio volumio[26928]: info: Asound.conf file unchanged, so no further update is needed Jan 08 12:43:37 volumio volumio[26928]: info: Output device has changed, restarting MPD Jan 08 12:43:37 volumio sudo[27351]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio sudo[27359]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 08 12:43:37 volumio volumio[26928]: info: Output device has changed, restarting Shairport Sync Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:37 volumio sudo[27359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio sudo[27362]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:43:37 volumio sudo[27362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio sudo[27362]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio sudo[27359]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:37 volumio sudo[27363]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:43:37 volumio sudo[27363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:37 volumio volumio[26928]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:43:37 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:43:37 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:43:37 volumio systemd[1]: mpd.service: Consumed 1.735s CPU time. Jan 08 12:43:37 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:43:37 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:43:37 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:43:37 volumio volumio[26928]: info: MPD Permissions set Jan 08 12:43:37 volumio volumio[26928]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:43:37 volumio volumio[26928]: info: Shairport-Sync Started Jan 08 12:43:37 volumio volumio[26928]: Error adding Membership: Error: addMembership EINVAL Jan 08 12:43:37 volumio volumio[26928]: info: Shairport-Sync Started Jan 08 12:43:37 volumio volumio[26928]: info: Shairport-Sync Started Jan 08 12:43:37 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:43:37 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:43:37 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:38 volumio sudo[27391]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:43:38 volumio sudo[27391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:38 volumio volumio[26928]: info: CoreCommandRouter::volumioGetState Jan 08 12:43:38 volumio volumio[26928]: info: CorePlayQueue::getTrack 0 Jan 08 12:43:38 volumio sudo[27391]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:38 volumio volumio[26928]: info: Starting Shairport Sync Jan 08 12:43:38 volumio sudo[27400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:43:38 volumio sudo[27400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:38 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 08 12:43:38 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:43:38 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:43:38 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:38 volumio sudo[27403]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 08 12:43:38 volumio volumio[26928]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 08 12:43:38 volumio sudo[27403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:38 volumio volumio[26928]: info: Spotify Successfully logged in Jan 08 12:43:38 volumio volumio[26928]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:43:38 volumio volumio[26928]: info: [1767897818184] CoreMusicLibrary::Adding element Spotify Jan 08 12:43:38 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source Bandcamp Discover Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source SoundCloud Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source YouTube2 Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source YouTube Music Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source Podcast Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source Volusonic Jan 08 12:43:38 volumio volumio[26928]: Cannot find translation for source Spotify Jan 08 12:43:38 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:43:38 volumio systemd[1]: Reloading. Jan 08 12:43:38 volumio sudo[27400]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:38 volumio volumio[26928]: info: Shairport-Sync Started Jan 08 12:43:38 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.58.55 Jan 08 12:43:38 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:38 volumio avahi-daemon[664]: Registering new address record for 169.254.58.55 on eth0.IPv4. Jan 08 12:43:38 volumio sudo[27392]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 12:43:38 volumio sudo[27392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 12:43:38 volumio sudo[27392]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:39 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:43:39 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.58.55 Jan 08 12:43:39 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:39 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:39 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:43:39 volumio volumio[26928]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:43:39 volumio ntpd[872]: IO: Listen normally on 9569 eth0 169.254.58.55:123 Jan 08 12:43:39 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Jan 08 12:43:39 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.58.55 Jan 08 12:43:39 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.58.55 Jan 08 12:43:39 volumio avahi-daemon[664]: Withdrawing address record for 169.254.58.55 on eth0. Jan 08 12:43:39 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:39 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:40 volumio volumio[26928]: info: go-librespot daemon successfully initialized Jan 08 12:43:40 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. Jan 08 12:43:40 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. Jan 08 12:43:41 volumio ntpd[872]: IO: Deleting interface #9569 eth0, 169.254.58.55#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Jan 08 12:43:41 volumio sudo[27403]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:41 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:41 volumio sudo[27485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:41 volumio sudo[27485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Jan 08 12:43:41 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:41 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:41 volumio sudo[27485]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:41 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:41 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 08 12:43:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:41 volumio go-librespot[27488]: go-librespot daemon starting... Jan 08 12:43:41 volumio sudo[27490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 08 12:43:41 volumio sudo[27490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:41 volumio go-librespot[27491]: time="2026-01-08T12:43:41-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:41 volumio go-librespot[27491]: time="2026-01-08T12:43:41-06:00" level=debug msg="app state loaded" Jan 08 12:43:41 volumio go-librespot[27491]: time="2026-01-08T12:43:41-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:41 volumio go-librespot[27491]: time="2026-01-08T12:43:41-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:41 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:41 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:41 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:41 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 08 12:43:41 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 08 12:43:41 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 08 12:43:41 volumio sudo[27490]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=info msg="zeroconf server listening on port 44347" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="obtained new client token: AACujrjEa14w9FiILF8lioU6Z1+/XUelMzkS7Xv0yAoLrzuy3AA8oQopmU6KyXRd9UIhmY5k112t6F+9FzLmp8MPRhf7eIYPkTlpPEUbHNUeiA5sY/RwK5mh2gtN5IN9BfFUpQeZTmdDVc9MJ5kZx8NrWcbk9IhzFwJNF5Wcrk8xtex6d2MCJcDOcg/Ab+OymN4QyTl6g1Ty9+cvWGsEbKFwzPSF5ic03l6apZtUOWf3uu20XTRx9QE=" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=debug msg="completed challenge" Jan 08 12:43:42 volumio go-librespot[27491]: time="2026-01-08T12:43:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:42 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:42 volumio sudo[27500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:42 volumio sudo[27500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:42 volumio sudo[27500]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:42 volumio volumio[26928]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 08 12:43:42 volumio sudo[27504]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 08 12:43:42 volumio sudo[27504]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:42 volumio sudo[27504]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:42 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 08 12:43:42 volumio sudo[27507]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 08 12:43:42 volumio sudo[27507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:42 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 08 12:43:42 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 08 12:43:42 volumio sudo[27507]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:43 volumio volumio[26928]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:43 volumio volumio[26928]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 12:43:43 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:43 volumio sudo[27514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:43 volumio sudo[27514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:43 volumio sudo[27514]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:44 volumio sudo[27517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:44 volumio sudo[27517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:44 volumio sudo[27517]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.177.240 Jan 08 12:43:44 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:44 volumio mpd[27483]: 2026-01-08T12:43:44 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 12:43:44 volumio avahi-daemon[664]: Registering new address record for 169.254.177.240 on eth0.IPv4. Jan 08 12:43:44 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:44 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:44 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:44 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:44 volumio sudo[27537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:44 volumio sudo[27537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:44 volumio sudo[27537]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 12:43:44 volumio sudo[27282]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio sudo[27272]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio sudo[27363]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:44 volumio volumio[26928]: error: MPD error: The expression evaluated to a falsy value: Jan 08 12:43:44 volumio volumio[26928]: assert.ok(self.idling) Jan 08 12:43:44 volumio volumio[26928]: error: The expression evaluated to a falsy value: Jan 08 12:43:44 volumio volumio[26928]: assert.ok(self.idling) Jan 08 12:43:44 volumio volumio[26928]: error: MPD error: The expression evaluated to a falsy value: Jan 08 12:43:44 volumio volumio[26928]: assert.ok(self.idling) Jan 08 12:43:44 volumio volumio[26928]: error: The expression evaluated to a falsy value: Jan 08 12:43:44 volumio volumio[26928]: assert.ok(self.idling) Jan 08 12:43:44 volumio volumio[26928]: info: MPD running with PID27483 Jan 08 12:43:44 volumio volumio[26928]: ,establishing connection Jan 08 12:43:44 volumio volumio[26928]: error: updateQueue error: null Jan 08 12:43:44 volumio volumio[26928]: error: updateQueue error: null Jan 08 12:43:45 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.177.240 Jan 08 12:43:45 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:45 volumio sudo[27544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:45 volumio sudo[27544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:45 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:43:45 volumio sudo[27544]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Jan 08 12:43:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:45 volumio go-librespot[27547]: go-librespot daemon starting... Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="app state loaded" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:45 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.177.240 Jan 08 12:43:45 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.177.240 Jan 08 12:43:45 volumio avahi-daemon[664]: Withdrawing address record for 169.254.177.240 on eth0. Jan 08 12:43:45 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=info msg="zeroconf server listening on port 46447" Jan 08 12:43:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:45 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:45 volumio volumio[26928]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 08 12:43:45 volumio sudo[27572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 08 12:43:45 volumio sudo[27572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="obtained new client token: AADciLLqvjsr9/ShexLhSmcKE2XIaMkY+w7Z2V2lY2PGXjA99cvxGX/1WDc4kisekKmqyzTTkYj2c59tfG/DuHT9aQ9B69VzZYMVsdhhS3yfi3+X/6L/tTqMa5zyyKS7043O7t7PN+zGEjq7sOAw6HaU+yL++jvad7a4yv7bnp6tFq6O2Ce7pdfkoDgYjbqcdaIhZ2Ww0NsBgm2L8UFANoKkJxOL78+2jrPYFH8KQWUGnJ0VLjLXp0zbvg==" Jan 08 12:43:45 volumio sudo[27572]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:45 volumio volumio[26928]: info: Completed starting Core Plugins Jan 08 12:43:45 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:45 volumio volumio[26928]: info: ----- MyVolumio plugins startup ---- Jan 08 12:43:45 volumio volumio[26928]: info: ------------------------------------------- Jan 08 12:43:45 volumio volumio[26928]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:45 volumio go-librespot[27548]: time="2026-01-08T12:43:45-06:00" level=debug msg="completed challenge" Jan 08 12:43:46 volumio go-librespot[27548]: time="2026-01-08T12:43:46-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:46 volumio volumio[26928]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:46 volumio volumio[26928]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 12:43:47 volumio sudo[27575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:47 volumio sudo[27575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:47 volumio sudo[27577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:47 volumio sudo[27577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:47 volumio sudo[27580]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 12:43:47 volumio sudo[27580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:47 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 12:43:47 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 12:43:47 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 12:43:47 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 12:43:47 volumio sudo[27580]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:47 volumio mpd_monitor.sh[27583]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 12:43:47 volumio sudo[27575]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:47 volumio sudo[27577]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:47 volumio volumio[26928]: info: Successfully started MPD Monitor Jan 08 12:43:47 volumio volumio[26928]: info: Successfully started MPD Monitor Jan 08 12:43:47 volumio volumio[26928]: info: Successfully started MPD Monitor Jan 08 12:43:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Jan 08 12:43:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:49 volumio go-librespot[27601]: go-librespot daemon starting... Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="app state loaded" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:49 volumio volumio[26928]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="new websocket client" Jan 08 12:43:49 volumio volumio[26928]: info: Connection to go-librespot Websocket established Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=info msg="zeroconf server listening on port 39849" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="obtained new client token: AAD2sgGNk8426N+mm0EDQQA2gXRId+6yFu9kY/VfAFrubNP2+/Jb7NdqWM6dL4jXeO4kXT1iapNqzLsfjOBg4zpfy4/xQReHPJRNG9WPdd6OvjYEursvX8pToJwO14l10njqn+wtEzFXGfg3rR6V5Je82bRji2wer+dUS3OmO/is1hF7+bMbiMLxIwdlg+jLwZzjfFJXc8NFk1/Fo+1LUMY+AIXM2GuGeUeGr4L9j52k9vriLFiJ/yWimQ==" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=debug msg="completed challenge" Jan 08 12:43:49 volumio go-librespot[27602]: time="2026-01-08T12:43:49-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:49 volumio volumio[26928]: info: Connection to go-librespot Websocket closed Jan 08 12:43:50 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.241.186 Jan 08 12:43:50 volumio avahi-daemon[664]: Registering new address record for 169.254.241.186 on eth0.IPv4. Jan 08 12:43:50 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:50 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:50 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:50 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:51 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.241.186 Jan 08 12:43:51 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.241.186 Jan 08 12:43:51 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.241.186 Jan 08 12:43:51 volumio avahi-daemon[664]: Withdrawing address record for 169.254.241.186 on eth0. Jan 08 12:43:51 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:51 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:51 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:51 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:51 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:51 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:43:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Jan 08 12:43:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:53 volumio go-librespot[27643]: go-librespot daemon starting... Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="app state loaded" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.181744, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:53 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182166, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:53 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7824 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182342, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:53 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182542, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:53 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7825 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182717, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:53 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182851, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:53 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7826 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.182991, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:53 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.183128, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:53 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7827 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.183270, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:53 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:53 volumio nmbd[1048]: [2026/01/08 12:43:53.183431, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:53 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7828 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=info msg="zeroconf server listening on port 45903" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="obtained new client token: AAAinBKJdvkKNRthI0GXltQIy5peU4+VIDJUoiFGSPtxnBD94p2joSa27k7+O4StVqOWfZuju26fZ7E1ubm/hKHO41y4yUN3dXxcbd5ClxkzzIsDTXFX4HcusOxyYOJnAlXhRBqZ/pIkARaAxlQQhLpwHLePFVJVTSrKaNCQ4jjWfQYubteuYYXdV+IsF2NCjpW7uxyH4zeVUASTPt6ZM4KYULpH0j2kK3LotxW+rYLHsxg9eoKRQ0iXDw==" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=debug msg="completed challenge" Jan 08 12:43:53 volumio go-librespot[27644]: time="2026-01-08T12:43:53-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:54 volumio volumio[26928]: info: Getting Spotify volume Jan 08 12:43:54 volumio volumio[26928]: info: Initializing connection to go-librespot Websocket Jan 08 12:43:54 volumio volumio[26928]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.184958, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:54 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:54 volumio volumio[26928]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 12:43:54 volumio volumio[26928]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 08 12:43:54 volumio volumio[26928]: errno: -111, Jan 08 12:43:54 volumio volumio[26928]: code: 'ECONNREFUSED', Jan 08 12:43:54 volumio volumio[26928]: syscall: 'connect', Jan 08 12:43:54 volumio volumio[26928]: address: '127.0.0.1', Jan 08 12:43:54 volumio volumio[26928]: port: 9879, Jan 08 12:43:54 volumio volumio[26928]: response: undefined Jan 08 12:43:54 volumio volumio[26928]: } Jan 08 12:43:54 volumio volumio[26928]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185226, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:54 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7824 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185327, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:54 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185409, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:54 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7825 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185483, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:54 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185551, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:54 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7826 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185624, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:54 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185690, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:54 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7827 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185760, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:54 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:54 volumio nmbd[1048]: [2026/01/08 12:43:54.185825, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:54 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7828 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:54 volumio sudo[27665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 12:42' Jan 08 12:43:54 volumio sudo[27665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.187185, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:55 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.188785, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:55 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7824 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.188962, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:55 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189056, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:55 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7825 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189126, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:55 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189195, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:55 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7826 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189369, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:55 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189440, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:55 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7827 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189513, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 08 12:43:55 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Jan 08 12:43:55 volumio nmbd[1048]: [2026/01/08 12:43:55.189593, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Jan 08 12:43:55 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 7828 to IP 169.254.255.255 on subnet 169.254.241.186 Jan 08 12:43:55 volumio sudo[27665]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:55 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:55] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 08 12:43:55 volumio volumio-remote-updater[14193]: [2026-01-08 12:43:55] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 08 12:43:55 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:55 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 08 12:43:55 volumio systemd[1]: volumio.service: Consumed 51.677s CPU time. Jan 08 12:43:55 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 12:43:55 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 12:43:55 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 14881. Jan 08 12:43:55 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 12:43:55 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 08 12:43:55 volumio systemd[1]: volumio.service: Consumed 51.677s CPU time. Jan 08 12:43:55 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 08 12:43:55 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 12:43:56 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.74.181 Jan 08 12:43:56 volumio avahi-daemon[664]: Registering new address record for 169.254.74.181 on eth0.IPv4. Jan 08 12:43:56 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:43:56 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:56 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:56 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Jan 08 12:43:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:43:57 volumio go-librespot[27709]: go-librespot daemon starting... Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="app state loaded" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="stored credentials not found" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:43:57 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.74.181 Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=info msg="zeroconf server listening on port 37751" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="obtained new client token: AACKRZeZpImaLs58XnK3j3zvWfmpaz/h44p53UmqzAm7LYJE/QqFlGFzLXsyBEf0KwXGg1QrwP4SpZUhAXFA+fS1klGYpBcWnoLOe4NCXuRhNKiIuoPiVq7x4EbQVScivW1i2IrRGhtMFgXF8gdFikOR3Y4l7I7GmSjsZpe/dtg9C51ubwgHTE4G+H0UchZJhXOK9KXTbjYgP/juAt9TS1mY7UHMNpoMgHJB1Qs1lfdvEN31XNtWRWV1yg==" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="completed keyexchange" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=debug msg="completed challenge" Jan 08 12:43:57 volumio go-librespot[27710]: time="2026-01-08T12:43:57-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:43:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:43:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:43:57 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:43:57 volumio volumio[27678]: info: ------------------------------------------- Jan 08 12:43:57 volumio volumio[27678]: info: ----- Volumio3 ---- Jan 08 12:43:57 volumio volumio[27678]: info: ------------------------------------------- Jan 08 12:43:57 volumio volumio[27678]: info: ----- System startup ---- Jan 08 12:43:57 volumio volumio[27678]: info: ------------------------------------------- Jan 08 12:43:57 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.74.181 Jan 08 12:43:57 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.74.181 Jan 08 12:43:57 volumio avahi-daemon[664]: Withdrawing address record for 169.254.74.181 on eth0. Jan 08 12:43:57 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:43:58 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:43:58 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:58 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:43:58 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:43:58 volumio volumio[27678]: info: MYVOLUMIO Environment detected Jan 08 12:43:58 volumio volumio[27678]: info: Plugin folders cleanup Jan 08 12:43:58 volumio volumio[27678]: info: Scanning into folder /volumio/app/plugins/ Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category audio_interface Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category miscellanea Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category music_service Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category plugins.json Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category system_controller Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category user_interface Jan 08 12:43:58 volumio volumio[27678]: info: Scanning into folder /data/plugins/ Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category audio_interface Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category music_service Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category system_controller Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category system_hardware Jan 08 12:43:58 volumio volumio[27678]: info: Scanning category user_interface Jan 08 12:43:58 volumio volumio[27678]: info: Plugin folders cleanup completed Jan 08 12:43:58 volumio volumio[27678]: info: ------------------------------------------- Jan 08 12:43:58 volumio volumio[27678]: info: ----- Core plugins startup ---- Jan 08 12:43:58 volumio volumio[27678]: info: ------------------------------------------- Jan 08 12:43:58 volumio volumio[27678]: info: Loading plugins from folder /volumio/app/plugins/ Jan 08 12:43:58 volumio volumio[27678]: info: Adding plugin upnp to MyMusic Plugins Jan 08 12:43:58 volumio volumio[27678]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 08 12:43:58 volumio volumio[27678]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 08 12:43:58 volumio volumio[27678]: info: Loading plugins from folder /data/plugins/ Jan 08 12:43:58 volumio volumio[27678]: info: Loading plugin "system"... Jan 08 12:43:58 volumio volumio[27678]: info: Loading plugin "appearance"... Jan 08 12:43:59 volumio volumio[27678]: info: Loading plugin "network"... Jan 08 12:43:59 volumio volumio[27678]: info: Refreshing Cached IP Addresses Jan 08 12:43:59 volumio sudo[27747]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 12:43:59 volumio sudo[27747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:59 volumio sudo[27749]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 12:43:59 volumio sudo[27749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:59 volumio volumio[27678]: info: Loading plugin "services"... Jan 08 12:43:59 volumio sudo[27747]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:59 volumio sudo[27749]: pam_unix(sudo:session): session closed for user root Jan 08 12:43:59 volumio volumio[27678]: info: Loading plugin "alsa_controller"... Jan 08 12:43:59 volumio sudo[27756]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 08 12:43:59 volumio sudo[27756]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:43:59 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:43:59 volumio volumio[27678]: info: Loading plugin "wizard"... Jan 08 12:43:59 volumio volumio[27678]: info: Loading plugin "networkfs"... Jan 08 12:43:59 volumio volumio[27678]: info: Starting Udev Watcher for removable devices Jan 08 12:44:00 volumio volumio[27678]: info: Ignoring mount for partition: boot Jan 08 12:44:00 volumio volumio[27678]: info: Ignoring mount for partition: volumio Jan 08 12:44:00 volumio volumio[27678]: info: Ignoring mount for partition: volumio_data Jan 08 12:44:00 volumio volumio[27678]: info: Mounting Device Wikipedia Jan 08 12:44:00 volumio sudo[27786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 08 12:44:00 volumio sudo[27786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:00 volumio sudo[27786]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:00 volumio volumio[27678]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 08 12:44:00 volumio volumio[27678]: dmesg(1) may have more information after failed mount system call. Jan 08 12:44:00 volumio volumio[27678]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 08 12:44:00 volumio volumio[27678]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 08 12:44:00 volumio volumio[27678]: dmesg(1) may have more information after failed mount system call. Jan 08 12:44:00 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:44:00 volumio volumio[27678]: info: Loading plugin "volumio_command_line_client"... Jan 08 12:44:00 volumio volumio[27678]: info: Loading plugin "upnp"... Jan 08 12:44:00 volumio volumio[27678]: info: [1767897840175] Starting Upmpd Daemon Jan 08 12:44:00 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:44:00 volumio volumio[27678]: info: Loading plugin "my_music"... Jan 08 12:44:00 volumio volumio[27678]: info: Loading plugin "mpd"... Jan 08 12:44:00 volumio volumio-remote-updater[14193]: [2026-01-08 12:44:00] [connect] Successful connection Jan 08 12:44:00 volumio sudo[27756]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Jan 08 12:44:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:00 volumio go-librespot[27788]: go-librespot daemon starting... Jan 08 12:44:00 volumio volumio[27678]: info: Loading plugin "upnp_browser"... Jan 08 12:44:00 volumio go-librespot[27789]: time="2026-01-08T12:44:00-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:00 volumio go-librespot[27789]: time="2026-01-08T12:44:00-06:00" level=debug msg="app state loaded" Jan 08 12:44:00 volumio go-librespot[27789]: time="2026-01-08T12:44:00-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:00 volumio go-librespot[27789]: time="2026-01-08T12:44:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=info msg="zeroconf server listening on port 34321" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="obtained new client token: AABbDg5HZNZNpF0We/3X88JyaznJ403tG3Wx8rlz0/eFEIb2VU2Hre2TClOhJdWGlHfbl/h9Tb21JR9yeppiuPcz59+q+D9XyM1YLutPvXDzTzky9f33BCLA/BFIhihuyxc72V7V1UW6LxHcgDnreRvTdlko7XVpPyE6xm0DiI9NTAqoyqAA/JVrHeSJYana0faibnYolRt7zxWxNQDZ3alw1iisJKiB8wfBxoVrV49GRwgC5+H3/eav+w==" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=debug msg="completed challenge" Jan 08 12:44:01 volumio go-librespot[27789]: time="2026-01-08T12:44:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:01 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "alarm-clock"... Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "airplay_emulation"... Jan 08 12:44:03 volumio volumio[27678]: info: Starting Shairport Sync Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "last_100"... Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "webradio"... Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "i2s_dacs"... Jan 08 12:44:03 volumio volumio[27678]: info: I2S DAC not set, start Auto-detection Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "volumiodiscovery"... Jan 08 12:44:03 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.111.38 Jan 08 12:44:03 volumio avahi-daemon[664]: Registering new address record for 169.254.111.38 on eth0.IPv4. Jan 08 12:44:03 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** For more information see Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:44:03 volumio volumio[27678]: *** WARNING *** For more information see Jan 08 12:44:03 volumio node[27678]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 12:44:03 volumio node[27678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:44:03 volumio node[27678]: *** WARNING *** For more information see Jan 08 12:44:03 volumio node[27678]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 12:44:03 volumio node[27678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 12:44:03 volumio node[27678]: *** WARNING *** For more information see Jan 08 12:44:03 volumio volumio[27678]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 08 12:44:03 volumio volumio[27678]: info: Discovery: Started advertising with name: Volumio Jan 08 12:44:03 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:03 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:03 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:03 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 12:44:03 volumio volumio[27678]: info: Loading plugin "bandcamp"... Jan 08 12:44:04 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.111.38 Jan 08 12:44:04 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.111.38 Jan 08 12:44:04 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.111.38 Jan 08 12:44:04 volumio avahi-daemon[664]: Withdrawing address record for 169.254.111.38 on eth0. Jan 08 12:44:04 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:44:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:04 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:44:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Jan 08 12:44:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:04 volumio go-librespot[27832]: go-librespot daemon starting... Jan 08 12:44:04 volumio go-librespot[27833]: time="2026-01-08T12:44:04-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:04 volumio go-librespot[27833]: time="2026-01-08T12:44:04-06:00" level=debug msg="app state loaded" Jan 08 12:44:04 volumio go-librespot[27833]: time="2026-01-08T12:44:04-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:04 volumio go-librespot[27833]: time="2026-01-08T12:44:04-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=info msg="zeroconf server listening on port 42151" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="obtained new client token: AADomuKMG3bQGT2oNWf5mxacdR8pBb8InbURtwW2JUhoXM95ED8ZB2LHhIoLaNeQf8SFrbsRVEcFc5Dzbz8UyZuhZy+fejEhM4XWA2PWQO6vd0C6TZhL9RNdh0WB7ykBCNRe8Ac9wZ89C+15PkCGEptU3yngx3lnHbFv7bVvuOKBn+sY+SYaqsnexMBLbBnxTJSRXrmi/k+8IiYFgeD/6ZvyyshUdKCJ+dBtHFWwDLWferhxC1yh2cs=" Jan 08 12:44:05 volumio volumio[27678]: info: Plugin calmradio is not enabled Jan 08 12:44:05 volumio volumio[27678]: info: Loading plugin "soundcloud"... Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=debug msg="completed challenge" Jan 08 12:44:05 volumio go-librespot[27833]: time="2026-01-08T12:44:05-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:05 volumio volumio[27678]: info: Loading plugin "spop"... Jan 08 12:44:06 volumio kernel: hwmon hwmon1: Voltage normalised Jan 08 12:44:06 volumio volumio[27678]: info: Loading plugin "squeezelite_mc"... Jan 08 12:44:07 volumio volumio[27678]: info: Loading plugin "youtube2"... Jan 08 12:44:07 volumio volumio[27678]: info: Loading plugin "ytcr"... Jan 08 12:44:08 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 08 12:44:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Jan 08 12:44:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:08 volumio go-librespot[27845]: go-librespot daemon starting... Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=debug msg="app state loaded" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:44:08 volumio go-librespot[27846]: time="2026-01-08T12:44:08-06:00" level=info msg="zeroconf server listening on port 35913" Jan 08 12:44:09 volumio go-librespot[27846]: time="2026-01-08T12:44:09-06:00" level=debug msg="obtained new client token: AABaOElWFtI9+yX8rrH+pixQOUlvEFb3g+tOeFJ8wSIdjRuLuWVrWgZOVVzQpvZxN4uX6aZuNI/xg4ZPtHN/uhFNXsl50qOTZEmmqIIiEDoKoDgEih+qaXp3MyvkhyO2rCh+upmsd0Sxjt2kAcjoDyrdArMOhSubADCw0C2WXYVEcEPYLVEGJu57caNNaqT/JIj+vuuuX02VofINHBtz6Y65+A9ksQy0vNUePR8Tt1J7eYerCr7NeFE=" Jan 08 12:44:09 volumio go-librespot[27846]: time="2026-01-08T12:44:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:44:09 volumio go-librespot[27846]: time="2026-01-08T12:44:09-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:09 volumio go-librespot[27846]: time="2026-01-08T12:44:09-06:00" level=debug msg="completed challenge" Jan 08 12:44:09 volumio go-librespot[27846]: time="2026-01-08T12:44:09-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:10 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.9.94 Jan 08 12:44:10 volumio avahi-daemon[664]: Registering new address record for 169.254.9.94 on eth0.IPv4. Jan 08 12:44:10 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:44:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:10 volumio volumio[27678]: info: Loading plugin "ytmusic"... Jan 08 12:44:10 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.9.94 Jan 08 12:44:10 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.9.94 Jan 08 12:44:10 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.9.94 Jan 08 12:44:10 volumio avahi-daemon[664]: Withdrawing address record for 169.254.9.94 on eth0. Jan 08 12:44:10 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:44:10 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:44:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:11 volumio volumio[27678]: info: Plugin now_playing is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "outputs"... Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "albumart"... Jan 08 12:44:11 volumio volumio[27678]: info: Plugin example_plugin is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "inputs"... Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "updater_comm"... Jan 08 12:44:11 volumio volumio[27678]: info: Plugin mpdemulation is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "rest_api"... Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "websocket"... Jan 08 12:44:11 volumio volumio[27678]: info: Starting Socket.io Server version 1.7.4 Jan 08 12:44:11 volumio volumio[27678]: info: Plugin fusiondsp is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Plugin mpdoutput is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Plugin RoonBridge is not enabled Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "podcast"... Jan 08 12:44:11 volumio volumio[27678]: info: ControllerPodcast::constructor Jan 08 12:44:11 volumio volumio[27678]: info: Loading plugin "volusonic"... Jan 08 12:44:11 volumio volumio[27900]: Forking 3 albumart workers Jan 08 12:44:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Jan 08 12:44:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:12 volumio go-librespot[27941]: go-librespot daemon starting... Jan 08 12:44:12 volumio go-librespot[27942]: time="2026-01-08T12:44:12-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:12 volumio go-librespot[27942]: time="2026-01-08T12:44:12-06:00" level=debug msg="app state loaded" Jan 08 12:44:12 volumio go-librespot[27942]: time="2026-01-08T12:44:12-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:12 volumio go-librespot[27942]: time="2026-01-08T12:44:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:12 volumio volumio-remote-updater[14193]: [2026-01-08 12:44:12] [connect] Successful connection Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=info msg="zeroconf server listening on port 35269" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="obtained new client token: AADsARFDwDyAWmTbcRuvcCNRwpMre66CShkEvRelg+o9pca/2NTdhpVMmSCxii0goLIKasSuEgwfZsvAWRBYqpjsS8nBsPvI8bcrMa36RUWwkUvXYY9bW2Au+5YzUFeek3Tt5/FOJH8EX6p+hSiYMPqhFVEO2q4h3rGhipMVW6E63ml7z28cD/1O3BfAexXUSPJvbG5qmb3UQPi0Tdg5qE66HXp1Zrh8t2AueGRRF+8wiZdjoSZd/SuNlQ==" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=debug msg="completed challenge" Jan 08 12:44:13 volumio go-librespot[27942]: time="2026-01-08T12:44:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:14 volumio volumio[27912]: Starting albumart workers Jan 08 12:44:14 volumio volumio[27678]: info: Applying required configuration parameters for plugin volusonic Jan 08 12:44:14 volumio volumio[27678]: info: Loading plugin "backup_restore"... Jan 08 12:44:14 volumio volumio[27911]: Starting albumart workers Jan 08 12:44:14 volumio volumio[27910]: Starting albumart workers Jan 08 12:44:14 volumio volumio[27678]: info: Applying required configuration parameters for plugin backup_restore Jan 08 12:44:14 volumio volumio[27678]: info: Plugin rpi_eeprom_config is not enabled Jan 08 12:44:14 volumio volumio[27678]: info: Plugin rpi_eeprom_updater is not enabled Jan 08 12:44:14 volumio volumio[27678]: info: Loading plugin "scheduledrestart"... Jan 08 12:44:15 volumio volumio[27678]: info: Applying required configuration parameters for plugin scheduledrestart Jan 08 12:44:15 volumio volumio[27678]: info: Plugin Bluetoothremote is not enabled Jan 08 12:44:15 volumio volumio[27678]: info: Plugin music_services_shield is not enabled Jan 08 12:44:15 volumio volumio[27678]: info: Loading plugin "Systeminfo"... Jan 08 12:44:15 volumio volumio[27678]: info: Plugin peppymeterbasic is not enabled Jan 08 12:44:15 volumio volumio[27678]: info: Loading plugin "peppyspectrum"... Jan 08 12:44:16 volumio volumio[27678]: info: Loading i18n strings for locale en Jan 08 12:44:16 volumio volumio[27678]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 08 12:44:16 volumio volumio[27678]: Updating browse sources language Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::initPlayerControls Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: Express server listening on port 3000 Jan 08 12:44:16 volumio volumio[27678]: [Metrics] WebUI: 19s 22.21ms Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::resetVolumioState Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::getcurrentVolume Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:16 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.122.155 Jan 08 12:44:16 volumio avahi-daemon[664]: Registering new address record for 169.254.122.155 on eth0.IPv4. Jan 08 12:44:16 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:44:16 volumio sudo[27977]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 12:44:16 volumio sudo[27977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:16 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:16 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:16 volumio sudo[27977]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:16 volumio sudo[27983]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 12:44:16 volumio sudo[27983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio sudo[27983]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:16 volumio volumio[27678]: info: Volumio Network Manager: Network status updated: 1 Jan 08 12:44:16 volumio volumio[27678]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::pushState Jan 08 12:44:16 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioPushState Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::updateTrackBlock Jan 08 12:44:16 volumio volumio[27678]: info: CorePlayQueue::getTrackBlock Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:44:16 volumio volumio-remote-updater[14193]: [2026-01-08 12:44:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767897852 101 Jan 08 12:44:16 volumio volumio[27678]: 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 Jan 08 12:44:16 volumio volumio[27678]: info: Reloading queue from file Jan 08 12:44:16 volumio volumio[27678]: info: Setting Device type: Raspberry PI Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::setRepeat null single undefined Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::pushState Jan 08 12:44:16 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioPushState Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::setRandom null Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::pushState Jan 08 12:44:16 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioPushState Jan 08 12:44:16 volumio volumio[27678]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:44:16 volumio volumio[27678]: info: CoreStateMachine::pushState Jan 08 12:44:16 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioPushState Jan 08 12:44:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Jan 08 12:44:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:16 volumio volumio[27678]: info: Completed loading Core Plugins Jan 08 12:44:16 volumio volumio[27678]: info: Preparing to generate the ALSA configuration file Jan 08 12:44:16 volumio sudo[28005]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 12:44:16 volumio sudo[28005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio volumio[27678]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 08 12:44:16 volumio volumio[27678]: info: Reading ALSA contributions from plugins. Jan 08 12:44:16 volumio volumio[27678]: info: Asound.conf file unchanged, so no further update is needed Jan 08 12:44:16 volumio volumio[27678]: info: Output device has changed, restarting MPD Jan 08 12:44:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:16 volumio go-librespot[28006]: go-librespot daemon starting... Jan 08 12:44:16 volumio volumio[27678]: info: Output device has changed, restarting Shairport Sync Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.122.155 Jan 08 12:44:16 volumio go-librespot[28010]: time="2026-01-08T12:44:16-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:16 volumio go-librespot[28010]: time="2026-01-08T12:44:16-06:00" level=debug msg="app state loaded" Jan 08 12:44:16 volumio go-librespot[28010]: time="2026-01-08T12:44:16-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:16 volumio go-librespot[28010]: time="2026-01-08T12:44:16-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:16 volumio sudo[28005]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:16 volumio sudo[28016]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:44:16 volumio sudo[28009]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:44:16 volumio sudo[28009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio sudo[28016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio sudo[28009]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:16 volumio volumio[27678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:44:16 volumio volumio[27678]: info: ___________ START PLUGINS ___________ Jan 08 12:44:16 volumio volumio[27678]: info: ControllerMpd::onStart: Initializing MPD Jan 08 12:44:16 volumio volumio[27678]: info: Creating MPD Configuration file Jan 08 12:44:16 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:16 volumio volumio[27678]: info: [1767897856894] CoreMusicLibrary::Adding element Media Servers Jan 08 12:44:16 volumio sudo[28025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:16 volumio sudo[28025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio sudo[28027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:44:16 volumio sudo[28027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.122.155 Jan 08 12:44:16 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.122.155 Jan 08 12:44:16 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:44:16 volumio avahi-daemon[664]: Withdrawing address record for 169.254.122.155 on eth0. Jan 08 12:44:16 volumio sudo[28025]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:16 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:17 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:44:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:44:17 volumio systemd[1]: mpd.service: Consumed 4.046s CPU time. Jan 08 12:44:17 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:44:17 volumio volumio[27678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:44:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:44:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:44:17 volumio volumio[27678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:17 volumio volumio[27678]: info: [1767897857126] CoreMusicLibrary::Adding element Last_100 Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:17 volumio volumio[27678]: info: [1767897857138] CoreMusicLibrary::Adding element Webradio Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:44:17 volumio volumio[27678]: info: Initializing BBC Radios Jan 08 12:44:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:44:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 08 12:44:17 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:44:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:44:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=info msg="zeroconf server listening on port 39623" Jan 08 12:44:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:44:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:44:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:17 volumio volumio[27678]: info: [1767897857331] CoreMusicLibrary::Adding element Bandcamp Discover Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:17 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:17 volumio volumio[27678]: info: [1767897857350] CoreMusicLibrary::Adding element SoundCloud Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:17 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:17 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:17 volumio volumio[27678]: info: Creating Spotify config file Jan 08 12:44:17 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="obtained new client token: AACnoa/xIN1e0FjmZ2BElGTTrSIT14Pgt5s4zr2RmG50jqvv/msEMuCVu7wegx/Ip1GqGrAo4alnZaxJLr6JelKx6MsKaqwPzzN7HX0vA/NSWOdvVf2bpocJhGL0VexcYNZSsI5dlBSPKWVFywWiNKa/GchZUqShFb4MUDxGuiOqVrrdbbeAcu39roIa6A/z3hfO5nfFn3O8SAEhGnKzebLmjG/kdooQNi/v97WPYUCOkCyy+0cL7VrV/w==" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=debug msg="completed challenge" Jan 08 12:44:17 volumio go-librespot[28010]: time="2026-01-08T12:44:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:17 volumio sudo[28071]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 12:44:17 volumio sudo[28071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 12:44:17 volumio sudo[28071]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:18 volumio volumio[27678]: info: [squeezelite_mc] Starting proxy server... Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:18 volumio volumio[27678]: info: [1767897858041] CoreMusicLibrary::Adding element YouTube2 Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:18 volumio volumio[27678]: info: [1767897858073] CoreMusicLibrary::Adding element YouTube Music Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:18 volumio volumio[27678]: info: [1767897858092] CoreMusicLibrary::Adding element Podcast Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Podcast Jan 08 12:44:18 volumio volumio[27678]: info: Loading i18n strings for locale en Jan 08 12:44:18 volumio volumio[27678]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 08 12:44:18 volumio volumio[27678]: Updating browse sources language Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Podcast Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Podcast Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:18 volumio volumio[27678]: info: [1767897858173] CoreMusicLibrary::Adding element Volusonic Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Podcast Jan 08 12:44:18 volumio volumio[27678]: Cannot find translation for source Volusonic Jan 08 12:44:18 volumio volumio[27678]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 08 12:44:18 volumio volumio[27678]: info: Volumio Calling Home Jan 08 12:44:18 volumio volumio[27678]: info: [squeezelite_mc] Proxy server started on port 34537 Jan 08 12:44:18 volumio volumio[27678]: info: Preparing to generate the ALSA configuration file Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 12:44:18 volumio volumio[27678]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 08 12:44:18 volumio volumio[27678]: info: Discovery: Found device Volumio Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioGetState Jan 08 12:44:18 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:18 volumio volumio[27678]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 08 12:44:18 volumio volumio[27678]: info: Discovery: Found device Volumio Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioGetState Jan 08 12:44:18 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:18 volumio volumio[27678]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 08 12:44:18 volumio volumio[27678]: info: Reading ALSA contributions from plugins. Jan 08 12:44:18 volumio volumio[27678]: info: MPD Permissions set Jan 08 12:44:18 volumio volumio[27678]: info: MPD Permissions set Jan 08 12:44:18 volumio volumio[27678]: info: Upmpdcli Daemon Started Jan 08 12:44:18 volumio volumio[27678]: info: Volumio called home Jan 08 12:44:18 volumio volumio[27678]: info: Spotify config file written Jan 08 12:44:18 volumio sudo[28080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 12:44:18 volumio sudo[28080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:18 volumio volumio[27678]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 08 12:44:18 volumio volumio[27678]: info: VolumeController:: Volume=100 Mute =false Jan 08 12:44:18 volumio volumio[27678]: info: CoreStateMachine::pushState Jan 08 12:44:18 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:18 volumio volumio[27678]: info: CoreCommandRouter::volumioPushState Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Server discovery started Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Player finder started Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 08 12:44:19 volumio sudo[28080]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:19 volumio go-librespot[28082]: go-librespot daemon starting... Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="app state loaded" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:19 volumio volumio[27678]: info: No need to fix Spotify hosts Jan 08 12:44:19 volumio volumio[27678]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=info msg="zeroconf server listening on port 35043" Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 08 12:44:19 volumio volumio[27678]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="obtained new client token: AAA2q0x3EBK61h0Ze0LAS+Bc1V8z9tmMZZBlrM+C7RbW9Ml9cwYGh87WLbLmYU2s4w07p4+M2ILh5qx7JDC9TQiry09iQs2VPFxSGy7HskPK0omnbHEOVIg7fvgZrhrGt328bbF485rni3eK4vkRDB6Bq1fNdqacKO0o4kEwmsxoxM71zEaJ7lNp/FS/+ZMxQOFUTww9oaIow5Wci0HdmmDBm2iZgMjwJRfz40nK4o6ASygchRrnefFeKg==" Jan 08 12:44:19 volumio volumio[27678]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:44:19 volumio volumio[27678]: SPOTIFY: BQCaXN6gRpojX5NYMqY4wFoTBT2MaWJcD0h8nw_Zw3TYpY9C1_k1-wEku7FUmsTNIAMSVZDtL1ar6Cle1AClihlNMUg6jOQR0SC_SlNFWJrEPJG2Jjpcv3qGp-Si82Bnx3jguMCzL1QR8tU8iqFPc1HOVMnLB5V2ueXSqPVUeyf7OIsHBjxVVllumcKL-K5QxVwt4J_byvWQcCpGgYVj-YT5bqRyg3SOafwockc Jan 08 12:44:19 volumio volumio[27678]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 08 12:44:19 volumio volumio[27678]: info: New Spotify access token = BQCaXN6gRpojX5NYMqY4wFoTBT2MaWJcD0h8nw_Zw3TYpY9C1_k1-wEku7FUmsTNIAMSVZDtL1ar6Cle1AClihlNMUg6jOQR0SC_SlNFWJrEPJG2Jjpcv3qGp-Si82Bnx3jguMCzL1QR8tU8iqFPc1HOVMnLB5V2ueXSqPVUeyf7OIsHBjxVVllumcKL-K5QxVwt4J_byvWQcCpGgYVj-YT5bqRyg3SOafwockc Jan 08 12:44:19 volumio volumio[27678]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 08 12:44:19 volumio volumio[27678]: info: Starting Shairport Sync Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 12:44:19 volumio volumio[27678]: info: Starting Shairport Sync Jan 08 12:44:19 volumio volumio[27678]: info: Starting Shairport Sync Jan 08 12:44:19 volumio sudo[28106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="completed keyexchange" Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=debug msg="completed challenge" Jan 08 12:44:19 volumio sudo[28106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:19 volumio go-librespot[28084]: time="2026-01-08T12:44:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 08 12:44:19 volumio sudo[28108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:44:19 volumio sudo[28108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 12:44:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 12:44:20 volumio sudo[28110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:44:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:44:20 volumio sudo[28110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:44:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:20 volumio systemd[1]: shairport-sync.service: Consumed 2.064s CPU time. Jan 08 12:44:20 volumio volumio[27678]: info: Asound.conf file unchanged, so no further update is needed Jan 08 12:44:20 volumio volumio[27678]: info: Output device has changed, restarting MPD Jan 08 12:44:20 volumio sudo[28104]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Jan 08 12:44:20 volumio sudo[28104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:20 volumio sudo[28106]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio volumio[27678]: info: Output device has changed, restarting Shairport Sync Jan 08 12:44:20 volumio sudo[28130]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 12:44:20 volumio sudo[28130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:20 volumio sudo[28133]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 12:44:20 volumio sudo[28133]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio sudo[28130]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio sudo[28104]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:44:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:44:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:20 volumio volumio[27678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 12:44:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:20 volumio sudo[28108]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio sudo[28110]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 08 12:44:20 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 12:44:20 volumio systemd[1]: mpd.service: Consumed 2.943s CPU time. Jan 08 12:44:20 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 08 12:44:20 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 12:44:20 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 12:44:20 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 12:44:20 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 12:44:20 volumio volumio[27678]: info: MPD Permissions set Jan 08 12:44:20 volumio volumio[27678]: info: Shairport-Sync Started Jan 08 12:44:20 volumio volumio[27678]: Error adding Membership: Error: addMembership EINVAL Jan 08 12:44:20 volumio volumio[27678]: info: Shairport-Sync Started Jan 08 12:44:20 volumio volumio[27678]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 08 12:44:20 volumio volumio[27678]: info: Shairport-Sync Started Jan 08 12:44:20 volumio sudo[28164]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 08 12:44:20 volumio sudo[28164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:20 volumio sudo[28164]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio volumio[27678]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::volumioGetState Jan 08 12:44:20 volumio volumio[27678]: info: CorePlayQueue::getTrack 0 Jan 08 12:44:20 volumio sudo[28159]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 12:44:20 volumio sudo[28159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 12:44:20 volumio sudo[28159]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:20 volumio volumio[27678]: info: Starting Shairport Sync Jan 08 12:44:20 volumio volumio[27678]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Jan 08 12:44:20 volumio volumio[27678]: info: Spotify Successfully logged in Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 12:44:20 volumio volumio[27678]: info: [1767897860934] CoreMusicLibrary::Adding element Spotify Jan 08 12:44:20 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source Bandcamp Discover Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source SoundCloud Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source YouTube2 Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source YouTube Music Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source Podcast Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source Volusonic Jan 08 12:44:20 volumio volumio[27678]: Cannot find translation for source Spotify Jan 08 12:44:20 volumio sudo[28177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 12:44:20 volumio sudo[28177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:21 volumio sudo[28168]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 08 12:44:21 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 12:44:21 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 12:44:21 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:21 volumio sudo[28168]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:21 volumio sudo[28168]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:21 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 12:44:21 volumio volumio[27678]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 08 12:44:21 volumio sudo[28177]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:21 volumio volumio[27678]: info: Shairport-Sync Started Jan 08 12:44:21 volumio sudo[28182]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 08 12:44:21 volumio sudo[28182]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:21 volumio systemd[1]: Reloading. Jan 08 12:44:21 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:21 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:21 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 12:44:21 volumio volumio[27678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 12:44:22 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.176.171 Jan 08 12:44:22 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 08 12:44:22 volumio avahi-daemon[664]: Registering new address record for 169.254.176.171 on eth0.IPv4. Jan 08 12:44:22 volumio volumio[27678]: info: go-librespot daemon successfully initialized Jan 08 12:44:22 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.176.171 Jan 08 12:44:23 volumio volumio[27678]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:44:23 volumio ntpd[872]: IO: Listen normally on 9570 eth0 169.254.176.171:123 Jan 08 12:44:23 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Jan 08 12:44:23 volumio volumio[27678]: Error: addMembership ENODEV Jan 08 12:44:23 volumio volumio[27678]: at Socket.addMembership (node:dgram:860:11) Jan 08 12:44:23 volumio volumio[27678]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Jan 08 12:44:23 volumio volumio[27678]: errno: -19, Jan 08 12:44:23 volumio volumio[27678]: code: 'ENODEV', Jan 08 12:44:23 volumio volumio[27678]: syscall: 'addMembership' Jan 08 12:44:23 volumio volumio[27678]: } Jan 08 12:44:23 volumio volumio[27678]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 12:44:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.176.171 Jan 08 12:44:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.176.171 Jan 08 12:44:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 08 12:44:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.176.171 on eth0. Jan 08 12:44:23 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 08 12:44:24 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. Jan 08 12:44:24 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. Jan 08 12:44:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Jan 08 12:44:24 volumio sudo[28182]: pam_unix(sudo:session): session closed for user root Jan 08 12:44:24 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:24 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:24 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 12:44:24 volumio sudo[28262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 12:43' Jan 08 12:44:24 volumio go-librespot[28259]: go-librespot daemon starting... Jan 08 12:44:24 volumio sudo[28262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 12:44:24 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:24 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 08 12:44:24 volumio go-librespot[28263]: time="2026-01-08T12:44:24-06:00" level=info msg="running go-librespot 0.4.0" Jan 08 12:44:24 volumio go-librespot[28263]: time="2026-01-08T12:44:24-06:00" level=debug msg="app state loaded" Jan 08 12:44:24 volumio go-librespot[28263]: time="2026-01-08T12:44:24-06:00" level=debug msg="stored credentials not found" Jan 08 12:44:24 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 08 12:44:24 volumio go-librespot[28263]: time="2026-01-08T12:44:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 12:44:25 volumio go-librespot[28263]: time="2026-01-08T12:44:25-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 08 12:44:25 volumio go-librespot[28263]: time="2026-01-08T12:44:25-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 08 12:44:25 volumio go-librespot[28263]: time="2026-01-08T12:44:25-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"