Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::initPlayerControls Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio go-librespot[17657]: time="2025-12-30T11:17:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: Express server listening on port 3000 Dec 30 11:17:00 volumio volumio[17379]: [Metrics] WebUI: 19s 11.47ms Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::resetVolumioState Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::getcurrentVolume Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:00 volumio go-librespot[17657]: time="2025-12-30T11:17:00-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:00 volumio go-librespot[17657]: time="2025-12-30T11:17:00-06:00" level=debug msg="completed challenge" Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:00 volumio go-librespot[17657]: time="2025-12-30T11:17:00-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 " Dec 30 11:17:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:00 volumio sudo[17669]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:17:00 volumio sudo[17669]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio sudo[17671]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:17:00 volumio sudo[17671]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio sudo[17669]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:00 volumio sudo[17671]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:00 volumio volumio[17379]: info: Volumio Network Manager: Network status updated: 1 Dec 30 11:17:00 volumio volumio[17379]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::pushState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::updateTrackBlock Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrackBlock Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:00 volumio volumio-remote-updater[702]: [2025-12-30 11:17:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767115016 101 Dec 30 11:17:00 volumio volumio[17379]: 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 Dec 30 11:17:00 volumio volumio[17379]: info: Reloading queue from file Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::setRepeat null single undefined Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::pushState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::setRandom null Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::pushState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:00 volumio volumio[17379]: info: Setting Device type: Raspberry PI Dec 30 11:17:00 volumio volumio[17379]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:00 volumio volumio[17379]: info: CoreStateMachine::pushState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:00 volumio volumio[17379]: info: Completed loading Core Plugins Dec 30 11:17:00 volumio volumio[17379]: info: Preparing to generate the ALSA configuration file Dec 30 11:17:00 volumio sudo[17685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 11:17:00 volumio sudo[17685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio volumio[17379]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:17:00 volumio volumio[17379]: info: Discovery: Found device Volumio Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio volumio[17379]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:17:00 volumio volumio[17379]: info: Discovery: Found device Volumio Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:00 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:00 volumio sudo[17685]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:00 volumio volumio[17379]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:17:00 volumio volumio[17379]: info: Reading ALSA contributions from plugins. Dec 30 11:17:00 volumio volumio[17379]: info: Upmpdcli Daemon Started Dec 30 11:17:00 volumio volumio[17379]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:17:00 volumio volumio[17379]: info: Output device has changed, restarting MPD Dec 30 11:17:00 volumio volumio[17379]: info: Output device has changed, restarting Shairport Sync Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:00 volumio sudo[17688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:00 volumio sudo[17688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio sudo[17688]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:00 volumio sudo[17690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:00 volumio sudo[17690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio volumio[17379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:00 volumio volumio[17379]: info: ___________ START PLUGINS ___________ Dec 30 11:17:00 volumio volumio[17379]: info: ControllerMpd::onStart: Initializing MPD Dec 30 11:17:00 volumio volumio[17379]: info: Creating MPD Configuration file Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:00 volumio volumio[17379]: info: [1767115020636] CoreMusicLibrary::Adding element Media Servers Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:00 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 11:17:00 volumio sudo[17698]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:00 volumio sudo[17698]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:00 volumio sudo[17700]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:00 volumio sudo[17700]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:00 volumio sudo[17698]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:00 volumio volumio[17379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:00 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:00 volumio volumio[17379]: info: [1767115020758] CoreMusicLibrary::Adding element Last_100 Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:17:00 volumio systemd[1]: mpd.service: Consumed 5.838s CPU time. Dec 30 11:17:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:00 volumio volumio[17379]: info: [1767115020765] CoreMusicLibrary::Adding element Webradio Dec 30 11:17:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:17:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:00 volumio volumio[17379]: info: Initializing BBC Radios Dec 30 11:17:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:17:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:00 volumio volumio[17379]: info: [1767115020886] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:00 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:00 volumio volumio[17379]: info: [1767115020906] CoreMusicLibrary::Adding element SoundCloud Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:00 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:00 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:00 volumio volumio[17379]: info: Creating Spotify config file Dec 30 11:17:00 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:01 volumio sudo[17725]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:17:01 volumio sudo[17725]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:17:01 volumio sudo[17725]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:01 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.229.189 Dec 30 11:17:01 volumio avahi-daemon[664]: Registering new address record for 169.254.229.189 on eth0.IPv4. Dec 30 11:17:01 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:01 volumio volumio[17379]: info: [squeezelite_mc] Starting proxy server... Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:01 volumio volumio[17379]: info: [1767115021581] CoreMusicLibrary::Adding element YouTube2 Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:01 volumio volumio[17379]: info: [1767115021619] CoreMusicLibrary::Adding element YouTube Music Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:01 volumio volumio[17379]: info: [1767115021644] CoreMusicLibrary::Adding element Podcast Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Podcast Dec 30 11:17:01 volumio volumio[17379]: info: Loading i18n strings for locale en Dec 30 11:17:01 volumio volumio[17379]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 11:17:01 volumio volumio[17379]: Updating browse sources language Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Podcast Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Podcast Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:01 volumio volumio[17379]: info: [1767115021732] CoreMusicLibrary::Adding element Volusonic Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Podcast Dec 30 11:17:01 volumio volumio[17379]: Cannot find translation for source Volusonic Dec 30 11:17:01 volumio volumio[17379]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 11:17:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.229.189 Dec 30 11:17:01 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 11:17:01 volumio volumio[17379]: info: Volumio Calling Home Dec 30 11:17:02 volumio volumio[17379]: info: [squeezelite_mc] Proxy server started on port 42525 Dec 30 11:17:02 volumio volumio[17379]: info: Preparing to generate the ALSA configuration file Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:02 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.229.189 Dec 30 11:17:02 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.229.189 Dec 30 11:17:02 volumio avahi-daemon[664]: Withdrawing address record for 169.254.229.189 on eth0. Dec 30 11:17:02 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:02 volumio volumio[17379]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:17:02 volumio volumio[17379]: info: Reading ALSA contributions from plugins. Dec 30 11:17:02 volumio volumio[17379]: info: MPD Permissions set Dec 30 11:17:02 volumio volumio[17379]: info: MPD Permissions set Dec 30 11:17:02 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:02 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:02 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:02 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:02 volumio volumio[17379]: info: Spotify config file written Dec 30 11:17:02 volumio sudo[17766]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 11:17:02 volumio sudo[17766]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:02 volumio volumio[17379]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 11:17:02 volumio volumio[17379]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:02 volumio volumio[17379]: info: CoreStateMachine::pushState Dec 30 11:17:02 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:02 volumio volumio[17379]: info: [squeezelite_mc] Server discovery started Dec 30 11:17:02 volumio volumio[17379]: info: [squeezelite_mc] Player finder started Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 11:17:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:02 volumio go-librespot[17768]: go-librespot daemon starting... Dec 30 11:17:02 volumio volumio[17379]: info: Volumio called home Dec 30 11:17:02 volumio sudo[17766]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio go-librespot[17770]: time="2025-12-30T11:17:02-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:02 volumio go-librespot[17770]: time="2025-12-30T11:17:02-06:00" level=debug msg="app state loaded" Dec 30 11:17:02 volumio go-librespot[17770]: time="2025-12-30T11:17:02-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:02 volumio go-librespot[17770]: time="2025-12-30T11:17:02-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:02 volumio volumio[17379]: info: No need to fix Spotify hosts Dec 30 11:17:02 volumio volumio[17379]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-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]" Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-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]" Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-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]" Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-06:00" level=info msg="zeroconf server listening on port 45445" Dec 30 11:17:03 volumio volumio[17379]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 11:17:03 volumio volumio[17379]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 11:17:03 volumio volumio[17379]: 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 Dec 30 11:17:03 volumio volumio[17379]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:17:03 volumio volumio[17379]: SPOTIFY: BQDkSlwJzHYdbCtE1uzXAogG6C41e-a4W-DEJiGWmLioOCm_vwiUP2OeZkT7lg44S-Iw2fsxtqdTCqLHZS_QC1JMwky9coYznB5ybHOSImHUrsSF0KDAMwVyiidBIGByGCht5tQb1L7Whqfa2d74tpfKN4mHDbuGcodmMFE6Y6sUz3PgHdboHYo-NsogW6i1IemP8MQyg-PBAsM9iTk71eUzTWyp0lJydZwSc04 Dec 30 11:17:03 volumio volumio[17379]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:17:03 volumio volumio[17379]: info: New Spotify access token = BQDkSlwJzHYdbCtE1uzXAogG6C41e-a4W-DEJiGWmLioOCm_vwiUP2OeZkT7lg44S-Iw2fsxtqdTCqLHZS_QC1JMwky9coYznB5ybHOSImHUrsSF0KDAMwVyiidBIGByGCht5tQb1L7Whqfa2d74tpfKN4mHDbuGcodmMFE6Y6sUz3PgHdboHYo-NsogW6i1IemP8MQyg-PBAsM9iTk71eUzTWyp0lJydZwSc04 Dec 30 11:17:03 volumio volumio[17379]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-06:00" level=debug msg="obtained new client token: AACtqkEnMLjM3YMJwtp6wuokTC7DRAlBSQkq9pmseyqKsEAE1uoGVRJ0KQV+7nYHQp3LEjcUontGaPFSt9DPQeyGdtWP/c0h93NYe/9gmNyQAAGyg3KDmNpAJdVK6qUD7WcL82Bv+Hl/hvlIFBnQmEy07a+0qy2lMo+rpfibk3PG90q/j24Ri3yQRKZUKWkKFYaOkA3yTP4MNaPVgqRyTRuq58NPgt8mh74NawIkmf8GjYDvtMfbUxE=" Dec 30 11:17:03 volumio sudo[17791]: 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 Dec 30 11:17:03 volumio sudo[17791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio volumio[17379]: info: Starting Shairport Sync Dec 30 11:17:03 volumio sudo[17791]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio volumio[17379]: info: Starting Shairport Sync Dec 30 11:17:03 volumio volumio[17379]: info: Starting Shairport Sync Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:03 volumio sudo[17796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:03 volumio sudo[17794]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:03 volumio sudo[17796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio sudo[17794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-06:00" level=debug msg="completed challenge" Dec 30 11:17:03 volumio sudo[17798]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:03 volumio sudo[17798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio go-librespot[17770]: time="2025-12-30T11:17:03-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 " Dec 30 11:17:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:03 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:17:03 volumio volumio[17379]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 11:17:03 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:17:03 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:03 volumio systemd[1]: shairport-sync.service: Consumed 1.957s CPU time. Dec 30 11:17:03 volumio volumio[17379]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:17:03 volumio volumio[17379]: info: Output device has changed, restarting MPD Dec 30 11:17:03 volumio sudo[17806]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 11:17:03 volumio sudo[17806]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:03 volumio sudo[17794]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio sudo[17808]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:03 volumio sudo[17798]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio sudo[17808]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:03 volumio volumio[17379]: info: Output device has changed, restarting Shairport Sync Dec 30 11:17:03 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:03 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:03 volumio sudo[17796]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio sudo[17808]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio sudo[17806]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:03 volumio volumio[17379]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:03 volumio sudo[17812]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:03 volumio sudo[17812]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:17:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:17:04 volumio systemd[1]: mpd.service: Consumed 3.019s CPU time. Dec 30 11:17:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:17:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:17:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:17:04 volumio volumio[17379]: info: MPD Permissions set Dec 30 11:17:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:17:04 volumio volumio[17379]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 30 11:17:04 volumio volumio[17379]: info: Shairport-Sync Started Dec 30 11:17:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:17:04 volumio volumio[17379]: Error adding Membership: Error: addMembership EINVAL Dec 30 11:17:04 volumio volumio[17379]: info: Shairport-Sync Started Dec 30 11:17:04 volumio volumio[17379]: info: Shairport-Sync Started Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio sudo[17854]: 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 Dec 30 11:17:04 volumio sudo[17854]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:04 volumio sudo[17854]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:04 volumio volumio[17379]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:04 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 11:17:04 volumio volumio[17379]: info: Starting Shairport Sync Dec 30 11:17:04 volumio sudo[17863]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 11:17:04 volumio sudo[17863]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:04 volumio sudo[17865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:04 volumio sudo[17865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:04 volumio volumio[17379]: 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"} Dec 30 11:17:04 volumio volumio[17379]: info: Spotify Successfully logged in Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:04 volumio volumio[17379]: info: [1767115024512] CoreMusicLibrary::Adding element Spotify Dec 30 11:17:04 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source SoundCloud Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source YouTube2 Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source YouTube Music Dec 30 11:17:04 volumio systemd[1]: Reloading. Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source Podcast Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source Volusonic Dec 30 11:17:04 volumio volumio[17379]: Cannot find translation for source Spotify Dec 30 11:17:04 volumio sudo[17851]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:17:04 volumio sudo[17851]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:17:04 volumio sudo[17851]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:05 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:05 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:05 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:05 volumio volumio[17379]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:06 volumio volumio[17379]: info: go-librespot daemon successfully initialized Dec 30 11:17:06 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. Dec 30 11:17:06 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. Dec 30 11:17:07 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.23.172 Dec 30 11:17:07 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:07 volumio avahi-daemon[664]: Registering new address record for 169.254.23.172 on eth0.IPv4. Dec 30 11:17:07 volumio sudo[17863]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:07 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:07 volumio sudo[17905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:07 volumio sudo[17905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 30 11:17:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.172 Dec 30 11:17:07 volumio sudo[17905]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:07 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 11:17:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:07 volumio sudo[17908]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 11:17:07 volumio sudo[17908]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:07 volumio go-librespot[17909]: go-librespot daemon starting... Dec 30 11:17:07 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:17:07 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:17:07 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:07 volumio systemd[1]: shairport-sync.service: Consumed 1.562s CPU time. Dec 30 11:17:07 volumio go-librespot[17911]: time="2025-12-30T11:17:07-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:07 volumio go-librespot[17911]: time="2025-12-30T11:17:07-06:00" level=debug msg="app state loaded" Dec 30 11:17:07 volumio go-librespot[17911]: time="2025-12-30T11:17:07-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:07 volumio go-librespot[17911]: time="2025-12-30T11:17:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:08 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:08 volumio sudo[17865]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:08 volumio volumio[17379]: info: Shairport-Sync Started Dec 30 11:17:08 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-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]" Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-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]" Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-06:00" level=info msg="zeroconf server listening on port 44059" Dec 30 11:17:08 volumio ntpd[872]: IO: Listen normally on 488 eth0 169.254.23.172:123 Dec 30 11:17:08 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Dec 30 11:17:08 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 11:17:08 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-06:00" level=debug msg="obtained new client token: AADHjjpBXy9j4dUVIgPiJSdaVV7nMfWcjJI/ZwU4ml1TOLo34mZP2Quw7zPXQU26Dh81VfhQRj36nSzPmZfCK2OCDzyzJcfdwRd8f5zAVAnxPFPNCXIXUyXVan43wYg8BKB233nhDXKmBcP16USrK0+QWmETNm9NkhLqK02LrPbxThCQznNEUgCw5IglnRAHAW/JxnQr01whevr9dYRNtDIQFNgcrWmJ4GVjBbv+dJwNNh4tVGGGASAWvQ==" Dec 30 11:17:08 volumio sudo[17908]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:08 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.172 Dec 30 11:17:08 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.23.172 Dec 30 11:17:08 volumio avahi-daemon[664]: Withdrawing address record for 169.254.23.172 on eth0. Dec 30 11:17:08 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:08 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:08 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:08 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:08 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-06:00" level=debug msg="completed challenge" Dec 30 11:17:08 volumio go-librespot[17911]: time="2025-12-30T11:17:08-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 " Dec 30 11:17:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:08 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:08 volumio sudo[17950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:08 volumio sudo[17950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:09 volumio sudo[17950]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:09 volumio volumio[17379]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 11:17:09 volumio sudo[17954]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 11:17:09 volumio sudo[17954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:09 volumio sudo[17954]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:09 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 11:17:09 volumio sudo[17957]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 11:17:09 volumio sudo[17957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:09 volumio volumio[17379]: info: Initializing connection to go-librespot Websocket Dec 30 11:17:09 volumio volumio[17379]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 11:17:09 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:17:09 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:17:09 volumio sudo[17957]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:09 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:09 volumio sudo[17965]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:09 volumio sudo[17965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:09 volumio sudo[17965]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:10 volumio ntpd[872]: IO: Deleting interface #488 eth0, 169.254.23.172#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Dec 30 11:17:10 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:10 volumio sudo[17968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:10 volumio sudo[17968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:10 volumio sudo[17968]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:10 volumio mpd[17903]: 2025-12-30T11:17:10 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 11:17:11 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:11 volumio sudo[17971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:11 volumio sudo[17971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:11 volumio sudo[17971]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:11 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 11:17:11 volumio sudo[17812]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:11 volumio sudo[17700]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:11 volumio sudo[17690]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:11 volumio volumio[17379]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:17:11 volumio volumio[17379]: assert.ok(self.idling) Dec 30 11:17:11 volumio volumio[17379]: error: The expression evaluated to a falsy value: Dec 30 11:17:11 volumio volumio[17379]: assert.ok(self.idling) Dec 30 11:17:11 volumio volumio[17379]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:17:11 volumio volumio[17379]: assert.ok(self.idling) Dec 30 11:17:11 volumio volumio[17379]: error: The expression evaluated to a falsy value: Dec 30 11:17:11 volumio volumio[17379]: assert.ok(self.idling) Dec 30 11:17:11 volumio volumio[17379]: info: MPD running with PID17903 Dec 30 11:17:11 volumio volumio[17379]: ,establishing connection Dec 30 11:17:11 volumio volumio[17379]: error: updateQueue error: null Dec 30 11:17:11 volumio volumio[17379]: error: updateQueue error: null Dec 30 11:17:11 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 11:17:11 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:11 volumio sudo[17979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:11 volumio sudo[17979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 30 11:17:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:11 volumio go-librespot[17981]: go-librespot daemon starting... Dec 30 11:17:11 volumio sudo[17979]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:11 volumio go-librespot[17982]: time="2025-12-30T11:17:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:11 volumio go-librespot[17982]: time="2025-12-30T11:17:11-06:00" level=debug msg="app state loaded" Dec 30 11:17:11 volumio go-librespot[17982]: time="2025-12-30T11:17:11-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:11 volumio go-librespot[17982]: time="2025-12-30T11:17:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-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]" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-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]" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-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]" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=info msg="zeroconf server listening on port 40243" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=debug msg="obtained new client token: AADlAaDnEA6LVORz/0pxty/0tZ8oDckiX7ggU7P5R1LzrFWLolP6gFw9ri0EsmJKKVAa/oRXHM8DlGlVD3Rf0AO30r5Yg5c/oTBeqhcQFafqDJv7QsNTPcNNl79FI5jlvC8FzXKiHtArg1u9yhrJK0Sh+khDpLuD1+PP7cnFw2+frxYSeB6IS7bQUTuNpXGKIKk87aSRm1IHqVglqskSCWBEwHpetBf6Gd8HU5YKTZy3OPUlbmAnx5w=" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=debug msg="completed challenge" Dec 30 11:17:12 volumio volumio[17379]: info: Initializing connection to go-librespot Websocket Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-06:00" level=debug msg="new websocket client" Dec 30 11:17:12 volumio volumio[17379]: info: Connection to go-librespot Websocket established Dec 30 11:17:12 volumio go-librespot[17982]: time="2025-12-30T11:17:12-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 " Dec 30 11:17:12 volumio volumio[17379]: info: Connection to go-librespot Websocket closed Dec 30 11:17:12 volumio volumio[17379]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:12 volumio sudo[17990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:12 volumio sudo[17990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:12 volumio sudo[17990]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:12 volumio volumio[17379]: info: Completed starting Core Plugins Dec 30 11:17:12 volumio volumio[17379]: info: ------------------------------------------- Dec 30 11:17:12 volumio volumio[17379]: info: ----- MyVolumio plugins startup ---- Dec 30 11:17:12 volumio volumio[17379]: info: ------------------------------------------- Dec 30 11:17:12 volumio volumio[17379]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 11:17:13 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.54.250 Dec 30 11:17:13 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:13 volumio avahi-daemon[664]: Registering new address record for 169.254.54.250 on eth0.IPv4. Dec 30 11:17:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:14 volumio sudo[18023]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 11:17:14 volumio sudo[18023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:14 volumio sudo[18025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 11:17:14 volumio sudo[18025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:14 volumio sudo[18027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 11:17:14 volumio sudo[18027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:14 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 11:17:14 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 11:17:14 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 11:17:14 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 11:17:14 volumio sudo[18023]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:14 volumio sudo[18025]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.54.250 Dec 30 11:17:14 volumio sudo[18027]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:14 volumio mpd_monitor.sh[18031]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 11:17:14 volumio volumio[17379]: info: Successfully started MPD Monitor Dec 30 11:17:14 volumio volumio[17379]: info: Successfully started MPD Monitor Dec 30 11:17:14 volumio volumio[17379]: info: Successfully started MPD Monitor Dec 30 11:17:15 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.54.250 Dec 30 11:17:15 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.54.250 Dec 30 11:17:15 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:15 volumio avahi-daemon[664]: Withdrawing address record for 169.254.54.250 on eth0. Dec 30 11:17:15 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:15 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:15 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:15 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:15 volumio volumio[17379]: info: Getting Spotify volume Dec 30 11:17:15 volumio volumio[17379]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:17:15 volumio volumio[17379]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 11:17:15 volumio volumio[17379]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 11:17:15 volumio volumio[17379]: errno: -111, Dec 30 11:17:15 volumio volumio[17379]: code: 'ECONNREFUSED', Dec 30 11:17:15 volumio volumio[17379]: syscall: 'connect', Dec 30 11:17:15 volumio volumio[17379]: address: '127.0.0.1', Dec 30 11:17:15 volumio volumio[17379]: port: 9879, Dec 30 11:17:15 volumio volumio[17379]: response: undefined Dec 30 11:17:15 volumio volumio[17379]: } Dec 30 11:17:15 volumio volumio[17379]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:17:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Dec 30 11:17:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:15 volumio go-librespot[18063]: go-librespot daemon starting... Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=debug msg="app state loaded" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-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]" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-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]" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-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]" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=info msg="zeroconf server listening on port 39349" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-06:00" level=debug msg="obtained new client token: AADahviF8y6gbsa2GPN4lo2DDKBTgjPRvZKaoLt7Oe2jebYBBsdxlUWd4Amtwsm+c/JbrWPRzpdVw304Cye0/XqUqq5798fm1gHR9JxEYALLRoE5njCPhLhVdElYzkjDikT7FqQcoZIULoYPEoeBkaX+FD7NdbQ5AatdckgNYVsbItHlnjt3o9klI6Fuxku5iqBktqRVqXeFw9FcdgYkGQ6NY4s08HFpNhoVajGHDKMdVhCVbQTGi5jhKQ==" Dec 30 11:17:15 volumio go-librespot[18064]: time="2025-12-30T11:17:15-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" Dec 30 11:17:16 volumio go-librespot[18064]: time="2025-12-30T11:17:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 30 11:17:16 volumio go-librespot[18064]: time="2025-12-30T11:17:16-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:16 volumio go-librespot[18064]: time="2025-12-30T11:17:16-06:00" level=debug msg="completed challenge" Dec 30 11:17:16 volumio sudo[18073]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 11:16' Dec 30 11:17:16 volumio sudo[18073]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:16 volumio go-librespot[18064]: time="2025-12-30T11:17:16-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 " Dec 30 11:17:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:16 volumio sudo[18073]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:16 volumio volumio-remote-updater[702]: [2025-12-30 11:17:16] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 11:17:16 volumio volumio-remote-updater[702]: [2025-12-30 11:17:16] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 11:17:16 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:16 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 11:17:16 volumio systemd[1]: volumio.service: Consumed 45.700s CPU time. Dec 30 11:17:16 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 11:17:16 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 742. Dec 30 11:17:16 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 11:17:16 volumio systemd[1]: volumio.service: Consumed 45.700s CPU time. Dec 30 11:17:16 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 11:17:16 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 11:17:18 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:18 volumio volumio[18081]: info: ----- Volumio3 ---- Dec 30 11:17:18 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:18 volumio volumio[18081]: info: ----- System startup ---- Dec 30 11:17:18 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Dec 30 11:17:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:19 volumio go-librespot[18101]: go-librespot daemon starting... Dec 30 11:17:19 volumio volumio[18081]: info: MYVOLUMIO Environment detected Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="app state loaded" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:19 volumio volumio[18081]: info: Plugin folders cleanup Dec 30 11:17:19 volumio volumio[18081]: info: Scanning into folder /volumio/app/plugins/ Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category audio_interface Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category miscellanea Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category music_service Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category plugins.json Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category system_controller Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category user_interface Dec 30 11:17:19 volumio volumio[18081]: info: Scanning into folder /data/plugins/ Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category audio_interface Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category music_service Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category system_controller Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category system_hardware Dec 30 11:17:19 volumio volumio[18081]: info: Scanning category user_interface Dec 30 11:17:19 volumio volumio[18081]: info: Plugin folders cleanup completed Dec 30 11:17:19 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:19 volumio volumio[18081]: info: ----- Core plugins startup ---- Dec 30 11:17:19 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:19 volumio volumio[18081]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 11:17:19 volumio volumio[18081]: info: Adding plugin upnp to MyMusic Plugins Dec 30 11:17:19 volumio volumio[18081]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 11:17:19 volumio volumio[18081]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 11:17:19 volumio volumio[18081]: info: Loading plugins from folder /data/plugins/ Dec 30 11:17:19 volumio volumio[18081]: info: Loading plugin "system"... Dec 30 11:17:19 volumio volumio[18081]: info: Loading plugin "appearance"... Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-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]" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-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]" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=info msg="zeroconf server listening on port 44695" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="obtained new client token: AACu6eZjCuUjLrJ7ANcYmDmJzAYRok1WmnzoBZp0yEkUzTuuizZchqemQSBmIvJky2mnz3Ju6syiY7/WIHhT4q8+UTRjhll0YSZe98dJrjG6oiXQMvZEOVEfUUQ5LZQLC1b6GURfOXpdP8KxeB+hkfdTTO05qLygPPrYOSVFogc2LFwAO92r/3ZsyjB51Pk9I6SVT/6/j1Sg2uDeAxbpLzhFOQNHhLoFW0JePQZcOypmGNd5tq5fObD4jw==" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17:19-06:00" level=debug msg="completed challenge" Dec 30 11:17:19 volumio go-librespot[18105]: time="2025-12-30T11:17: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 " Dec 30 11:17:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:19 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.15.48 Dec 30 11:17:19 volumio avahi-daemon[664]: Registering new address record for 169.254.15.48 on eth0.IPv4. Dec 30 11:17:19 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:19 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:19 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:19 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:20 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.15.48 Dec 30 11:17:20 volumio volumio[18081]: info: Loading plugin "network"... Dec 30 11:17:20 volumio volumio[18081]: info: Refreshing Cached IP Addresses Dec 30 11:17:20 volumio sudo[18132]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:17:20 volumio sudo[18132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:20 volumio sudo[18134]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:17:20 volumio sudo[18134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:20 volumio sudo[18132]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:20 volumio volumio[18081]: info: Loading plugin "services"... Dec 30 11:17:20 volumio sudo[18134]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:20 volumio volumio[18081]: info: Loading plugin "alsa_controller"... Dec 30 11:17:20 volumio sudo[18142]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 11:17:20 volumio sudo[18142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:20 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.15.48 Dec 30 11:17:20 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.15.48 Dec 30 11:17:20 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:20 volumio avahi-daemon[664]: Withdrawing address record for 169.254.15.48 on eth0. Dec 30 11:17:20 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:20 volumio volumio[18081]: info: Loading plugin "wizard"... Dec 30 11:17:20 volumio volumio[18081]: info: Loading plugin "networkfs"... Dec 30 11:17:20 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:20 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:20 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:20 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:20 volumio volumio[18081]: info: Starting Udev Watcher for removable devices Dec 30 11:17:20 volumio volumio[18081]: info: Ignoring mount for partition: boot Dec 30 11:17:20 volumio volumio[18081]: info: Ignoring mount for partition: volumio Dec 30 11:17:20 volumio volumio[18081]: info: Ignoring mount for partition: volumio_data Dec 30 11:17:20 volumio volumio[18081]: info: Mounting Device Wikipedia Dec 30 11:17:20 volumio sudo[18187]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 11:17:20 volumio sudo[18187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:20 volumio sudo[18187]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:20 volumio volumio[18081]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 11:17:20 volumio volumio[18081]: dmesg(1) may have more information after failed mount system call. Dec 30 11:17:20 volumio volumio[18081]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 11:17:20 volumio volumio[18081]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 11:17:20 volumio volumio[18081]: dmesg(1) may have more information after failed mount system call. Dec 30 11:17:20 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:17:21 volumio volumio[18081]: info: Loading plugin "volumio_command_line_client"... Dec 30 11:17:21 volumio volumio[18081]: info: Loading plugin "upnp"... Dec 30 11:17:21 volumio volumio[18081]: info: [1767115041031] Starting Upmpd Daemon Dec 30 11:17:21 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:17:21 volumio volumio[18081]: info: Loading plugin "my_music"... Dec 30 11:17:21 volumio volumio[18081]: info: Loading plugin "mpd"... Dec 30 11:17:21 volumio sudo[18142]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:21 volumio volumio-remote-updater[702]: [2025-12-30 11:17:21] [connect] Successful connection Dec 30 11:17:21 volumio volumio[18081]: info: Loading plugin "upnp_browser"... Dec 30 11:17:21 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 11:17:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Dec 30 11:17:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:23 volumio go-librespot[18190]: go-librespot daemon starting... Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="app state loaded" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-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]" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-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]" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-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]" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=info msg="zeroconf server listening on port 44993" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="obtained new client token: AAAoH+3MkEstlObLTLZeN2n7x/2p2f4YGjsOvPOiGlqfkcsgFWxxG7dFZiX5fLRhcrhu3obGUr/vqD2FZXCPs4SI9Puu0k6QkGpGxA2L4aPtQ1BphVO1oxMz9KZd6RZfPv1ZLOugH26+dvrwEuwwjYJyXWlY6+CzmmTlMcOlTyQCbGSAFslMj6miOWgNNs1TjzOQPceF1c9ianrhEHi8AOnAkcaDVba8+s+Zx7tDi2lXQI1R5jT26vkw8A==" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-06:00" level=debug msg="completed challenge" Dec 30 11:17:23 volumio go-librespot[18191]: time="2025-12-30T11:17:23-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 " Dec 30 11:17:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "alarm-clock"... Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "airplay_emulation"... Dec 30 11:17:24 volumio volumio[18081]: info: Starting Shairport Sync Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "last_100"... Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "webradio"... Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "i2s_dacs"... Dec 30 11:17:24 volumio volumio[18081]: info: I2S DAC not set, start Auto-detection Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "volumiodiscovery"... Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** For more information see Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:17:24 volumio volumio[18081]: *** WARNING *** For more information see Dec 30 11:17:24 volumio node[18081]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 11:17:24 volumio node[18081]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:17:24 volumio node[18081]: *** WARNING *** For more information see Dec 30 11:17:24 volumio node[18081]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 11:17:24 volumio node[18081]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:17:24 volumio node[18081]: *** WARNING *** For more information see Dec 30 11:17:24 volumio volumio[18081]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 11:17:24 volumio volumio[18081]: info: Discovery: Started advertising with name: Volumio Dec 30 11:17:24 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:17:24 volumio volumio[18081]: info: Loading plugin "bandcamp"... Dec 30 11:17:25 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.81.86 Dec 30 11:17:25 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:25 volumio avahi-daemon[664]: Registering new address record for 169.254.81.86 on eth0.IPv4. Dec 30 11:17:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.81.86 Dec 30 11:17:26 volumio volumio[18081]: info: Plugin calmradio is not enabled Dec 30 11:17:26 volumio volumio[18081]: info: Loading plugin "soundcloud"... Dec 30 11:17:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.81.86 Dec 30 11:17:26 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.81.86 Dec 30 11:17:26 volumio avahi-daemon[664]: Withdrawing address record for 169.254.81.86 on eth0. Dec 30 11:17:26 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:26 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:26 volumio volumio[18081]: info: Loading plugin "spop"... Dec 30 11:17:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Dec 30 11:17:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:27 volumio go-librespot[18233]: go-librespot daemon starting... Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="app state loaded" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-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]" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-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]" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-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]" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=info msg="zeroconf server listening on port 35839" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="obtained new client token: AAD9AmXbQDhL7NHXag8XDsQZkXZxkZeqOqnzoGBNgF+EEArpDlEC2PQzWOeCMab6xjTBof4/78qdxOdzVncr8lp7s9QJhe3kmU4Y5+PrHW1Z9vibKE0Q+eXwf+eouKRYLVktMxs30/LTbSqrDjQv8loFBplWicpi8D+paaG58eB2Z0aDbzrMlXCkhTGlHphqu3G+9inBqguigoYLG60bsUaawrGL5/CHh/ctEE5mHYOu0FIO4PfNKr3PLw==" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-06:00" level=debug msg="completed challenge" Dec 30 11:17:27 volumio go-librespot[18234]: time="2025-12-30T11:17:27-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 " Dec 30 11:17:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:28 volumio volumio[18081]: info: Loading plugin "squeezelite_mc"... Dec 30 11:17:29 volumio volumio[18081]: info: Loading plugin "youtube2"... Dec 30 11:17:30 volumio volumio[18081]: info: Loading plugin "ytcr"... Dec 30 11:17:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Dec 30 11:17:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:31 volumio go-librespot[18255]: go-librespot daemon starting... Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="app state loaded" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-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]" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-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]" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-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]" Dec 30 11:17:31 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.131.46 Dec 30 11:17:31 volumio avahi-daemon[664]: Registering new address record for 169.254.131.46 on eth0.IPv4. Dec 30 11:17:31 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=info msg="zeroconf server listening on port 44951" Dec 30 11:17:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="obtained new client token: AAB6XOY5VgyiGRT+MKXZmViz1AsNrKjYWLQ110jnHpYsVjoB3ttPnFu7KobYQFJrr/n9/oEZIoxiSURqwPeunVzNG4Nc7xPdGe0Ta+ZZNwEgls2bxaiDonVFpIyVYHFwwyx4tpX3A8WBQtcAuVJoeV3iEVvuVPASu3jZEddvxKnygRMTH9byAwBQVKCzpoOh+67YPMFvgjNoj2398uInh9RED2z9dmPp8D1zjeAWsHM6TtBMBpnAR0HSog==" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-06:00" level=debug msg="completed challenge" Dec 30 11:17:31 volumio go-librespot[18256]: time="2025-12-30T11:17:31-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 " Dec 30 11:17:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.131.46 Dec 30 11:17:32 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.131.46 Dec 30 11:17:32 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.131.46 Dec 30 11:17:32 volumio avahi-daemon[664]: Withdrawing address record for 169.254.131.46 on eth0. Dec 30 11:17:32 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:32 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:32 volumio volumio[18081]: info: Loading plugin "ytmusic"... Dec 30 11:17:33 volumio volumio[18081]: info: Plugin now_playing is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "outputs"... Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "albumart"... Dec 30 11:17:33 volumio volumio[18081]: info: Plugin example_plugin is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "inputs"... Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "updater_comm"... Dec 30 11:17:33 volumio volumio[18081]: info: Plugin mpdemulation is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "rest_api"... Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "websocket"... Dec 30 11:17:33 volumio volumio[18081]: info: Starting Socket.io Server version 1.7.4 Dec 30 11:17:33 volumio volumio[18081]: info: Plugin fusiondsp is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Plugin mpdoutput is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Plugin RoonBridge is not enabled Dec 30 11:17:33 volumio volumio[18081]: info: Loading plugin "podcast"... Dec 30 11:17:33 volumio volumio-remote-updater[702]: [2025-12-30 11:17:33] [connect] Successful connection Dec 30 11:17:33 volumio volumio[18081]: info: ControllerPodcast::constructor Dec 30 11:17:34 volumio volumio[18081]: info: Loading plugin "volusonic"... Dec 30 11:17:34 volumio volumio[18295]: Forking 3 albumart workers Dec 30 11:17:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Dec 30 11:17:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:35 volumio go-librespot[18338]: go-librespot daemon starting... Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=debug msg="app state loaded" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-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]" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-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]" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-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]" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=info msg="zeroconf server listening on port 34905" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=debug msg="obtained new client token: AADf7x/tc8OPXUeMTtsUVPa5/gg/SsbyCKy9SOZuQIZ+H4ilJ+QKa0MNdxF7nRcnZ1OqPaIxl/OoG/QK45AV4UflCzdL+iXnmNqnLbM8Nmz4KKGzfZ8aweSboe6FtzkdEZml//OLYjsF2v06BsbsmAKZXXFvFToxWdpBLk5OpW5tlNqbmWCIcKMUWAn7RDOsPli0J2w2UijOSFgHDRbNMp5nQJ7BDwVWJ2IhpxaB2hAS91QnShPXc2EynA==" Dec 30 11:17:35 volumio go-librespot[18339]: time="2025-12-30T11:17:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:36 volumio go-librespot[18339]: time="2025-12-30T11:17:36-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:36 volumio go-librespot[18339]: time="2025-12-30T11:17:36-06:00" level=debug msg="completed challenge" Dec 30 11:17:36 volumio go-librespot[18339]: time="2025-12-30T11:17:36-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 " Dec 30 11:17:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:36 volumio volumio[18081]: info: Applying required configuration parameters for plugin volusonic Dec 30 11:17:36 volumio volumio[18081]: info: Loading plugin "backup_restore"... Dec 30 11:17:36 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.171.92 Dec 30 11:17:36 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:36 volumio avahi-daemon[664]: Registering new address record for 169.254.171.92 on eth0.IPv4. Dec 30 11:17:36 volumio volumio[18305]: Starting albumart workers Dec 30 11:17:36 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:36 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:36 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:37 volumio volumio[18307]: Starting albumart workers Dec 30 11:17:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.171.92 Dec 30 11:17:37 volumio volumio[18306]: Starting albumart workers Dec 30 11:17:37 volumio volumio[18081]: info: Applying required configuration parameters for plugin backup_restore Dec 30 11:17:37 volumio volumio[18081]: info: Plugin rpi_eeprom_config is not enabled Dec 30 11:17:37 volumio volumio[18081]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 11:17:37 volumio volumio[18081]: info: Loading plugin "scheduledrestart"... Dec 30 11:17:37 volumio volumio[18081]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 11:17:37 volumio volumio[18081]: info: Plugin Bluetoothremote is not enabled Dec 30 11:17:37 volumio volumio[18081]: info: Plugin music_services_shield is not enabled Dec 30 11:17:37 volumio volumio[18081]: info: Loading plugin "Systeminfo"... Dec 30 11:17:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.171.92 Dec 30 11:17:37 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.171.92 Dec 30 11:17:37 volumio avahi-daemon[664]: Withdrawing address record for 169.254.171.92 on eth0. Dec 30 11:17:37 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:37 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:37 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:37 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:37 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:38 volumio volumio[18081]: info: Plugin peppymeterbasic is not enabled Dec 30 11:17:38 volumio volumio[18081]: info: Loading plugin "peppyspectrum"... Dec 30 11:17:38 volumio volumio[18081]: info: Loading i18n strings for locale en Dec 30 11:17:38 volumio volumio[18081]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 11:17:38 volumio volumio[18081]: Updating browse sources language Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::initPlayerControls Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:38 volumio volumio[18081]: Express server listening on port 3000 Dec 30 11:17:38 volumio volumio[18081]: [Metrics] WebUI: 20s 633.79ms Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::resetVolumioState Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::getcurrentVolume Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:38 volumio sudo[18401]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:17:38 volumio sudo[18401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:38 volumio sudo[18401]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:38 volumio sudo[18403]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:17:38 volumio sudo[18403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:38 volumio sudo[18403]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:38 volumio volumio[18081]: info: Volumio Network Manager: Network status updated: 1 Dec 30 11:17:38 volumio volumio[18081]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::pushState Dec 30 11:17:38 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::updateTrackBlock Dec 30 11:17:38 volumio volumio[18081]: info: CorePlayQueue::getTrackBlock Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:38 volumio volumio[18081]: info: Reloading queue from file Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::setRepeat null single undefined Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::pushState Dec 30 11:17:38 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::setRandom null Dec 30 11:17:38 volumio volumio[18081]: info: CoreStateMachine::pushState Dec 30 11:17:38 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:38 volumio volumio[18081]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:38 volumio volumio[18081]: info: Setting Device type: Raspberry PI Dec 30 11:17:39 volumio volumio[18081]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:39 volumio volumio[18081]: info: CoreStateMachine::pushState Dec 30 11:17:39 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:39 volumio volumio[18081]: info: Completed loading Core Plugins Dec 30 11:17:39 volumio volumio[18081]: info: Preparing to generate the ALSA configuration file Dec 30 11:17:39 volumio sudo[18417]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 11:17:39 volumio sudo[18417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:39 volumio volumio[18081]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:17:39 volumio volumio[18081]: info: Discovery: Found device Volumio Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:39 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:39 volumio volumio[18081]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:17:39 volumio volumio[18081]: info: Discovery: Found device Volumio Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:39 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:39 volumio volumio[18081]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:17:39 volumio volumio[18081]: info: Reading ALSA contributions from plugins. Dec 30 11:17:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Dec 30 11:17:39 volumio volumio[18081]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:17:39 volumio volumio[18081]: info: Output device has changed, restarting MPD Dec 30 11:17:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:39 volumio volumio[18081]: info: Output device has changed, restarting Shairport Sync Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:39 volumio sudo[18421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:39 volumio sudo[18421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:39 volumio sudo[18421]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:39 volumio sudo[18423]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:39 volumio sudo[18423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:39 volumio volumio[18081]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:39 volumio volumio[18081]: info: ___________ START PLUGINS ___________ Dec 30 11:17:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:39 volumio go-librespot[18419]: go-librespot daemon starting... Dec 30 11:17:39 volumio sudo[18417]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:39 volumio volumio[18081]: info: ControllerMpd::onStart: Initializing MPD Dec 30 11:17:39 volumio volumio[18081]: info: Creating MPD Configuration file Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="app state loaded" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059242] CoreMusicLibrary::Adding element Media Servers Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 11:17:39 volumio sudo[18437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:39 volumio sudo[18437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:39 volumio sudo[18437]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:39 volumio sudo[18439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:39 volumio sudo[18439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059370] CoreMusicLibrary::Adding element Last_100 Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:17:39 volumio systemd[1]: mpd.service: Consumed 3.966s CPU time. Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059376] CoreMusicLibrary::Adding element Webradio Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:17:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:17:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:39 volumio volumio[18081]: info: Initializing BBC Radios Dec 30 11:17:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:17:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059469] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059483] CoreMusicLibrary::Adding element SoundCloud Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: info: Creating Spotify config file Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-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]" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-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]" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-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]" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=info msg="zeroconf server listening on port 43031" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="obtained new client token: AACep3FZUvpsydfV7vwgGDfhmNrtXsKbs2XxbuvG+1ullfKl3e8l4ERJ4/l+1IMs22VmdGFLbkJRb7wPzM/84N7wE/zBnZ9obxMFaf592T97gfQPuvtXihUAcmu76OnheqFmLqSShcryTo6OPiJslA/QLI4C23MGHFm9TAu/FELXp+fp2mgV7UCjr4ahJLQiLFzc2hseREwIXGqwE3jOISoaTrAqc/OxGhFYIuvFfM1hT8KDkmCWyDcV1A==" Dec 30 11:17:39 volumio sudo[18462]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:17:39 volumio sudo[18462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:17:39 volumio sudo[18462]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-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" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-06:00" level=debug msg="completed challenge" Dec 30 11:17:39 volumio volumio[18081]: info: [squeezelite_mc] Starting proxy server... Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059848] CoreMusicLibrary::Adding element YouTube2 Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio go-librespot[18430]: time="2025-12-30T11:17:39-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 " Dec 30 11:17:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059871] CoreMusicLibrary::Adding element YouTube Music Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059886] CoreMusicLibrary::Adding element Podcast Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Podcast Dec 30 11:17:39 volumio volumio[18081]: info: Loading i18n strings for locale en Dec 30 11:17:39 volumio volumio[18081]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 11:17:39 volumio volumio[18081]: Updating browse sources language Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Podcast Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Podcast Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:39 volumio volumio[18081]: info: [1767115059935] CoreMusicLibrary::Adding element Volusonic Dec 30 11:17:39 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Podcast Dec 30 11:17:39 volumio volumio[18081]: Cannot find translation for source Volusonic Dec 30 11:17:39 volumio volumio[18081]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 11:17:40 volumio volumio[18081]: info: Volumio Calling Home Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Proxy server started on port 40797 Dec 30 11:17:40 volumio volumio[18081]: info: Preparing to generate the ALSA configuration file Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:17:40 volumio volumio[18081]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:17:40 volumio volumio[18081]: info: Reading ALSA contributions from plugins. Dec 30 11:17:40 volumio volumio[18081]: info: MPD Permissions set Dec 30 11:17:40 volumio volumio[18081]: info: MPD Permissions set Dec 30 11:17:40 volumio volumio[18081]: info: Upmpdcli Daemon Started Dec 30 11:17:40 volumio volumio[18081]: info: Spotify config file written Dec 30 11:17:40 volumio sudo[18475]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 11:17:40 volumio sudo[18475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:40 volumio volumio[18081]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Dec 30 11:17:40 volumio volumio[18081]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:17:40 volumio volumio[18081]: info: CoreStateMachine::pushState Dec 30 11:17:40 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::volumioPushState Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Server discovery started Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Player finder started Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 11:17:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:40 volumio go-librespot[18478]: go-librespot daemon starting... Dec 30 11:17:40 volumio sudo[18475]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:40 volumio volumio[18081]: info: No need to fix Spotify hosts Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=debug msg="app state loaded" Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:40 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 11:17:40 volumio volumio[18081]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 11:17:40 volumio volumio[18081]: info: Volumio called home Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 11:17:40 volumio volumio[18081]: 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 Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-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]" Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-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]" Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-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]" Dec 30 11:17:40 volumio volumio[18081]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:17:40 volumio volumio[18081]: SPOTIFY: BQAAqc534K_oKOBQSJnI-qm8_q6_9-Pww5R7gLzwUl7KAmgGK91nos4jd3qDNEkIthJRCK2XeFosqCBJelLwPw8Lcmwp-fpyQL7YeAjK0VOoSuIZaL2a2iRP5AhmvJD3c33jOdN6xg-wdOh3BrePPZjUvaK7hsnAKsNpFKHrFFvTrcLHpEEcN_hdoH_7EupnirMm3RbYSws7LkPpTnFMSyvOPOoO_HyyWvXyQLg Dec 30 11:17:40 volumio volumio[18081]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:17:40 volumio volumio[18081]: info: New Spotify access token = BQAAqc534K_oKOBQSJnI-qm8_q6_9-Pww5R7gLzwUl7KAmgGK91nos4jd3qDNEkIthJRCK2XeFosqCBJelLwPw8Lcmwp-fpyQL7YeAjK0VOoSuIZaL2a2iRP5AhmvJD3c33jOdN6xg-wdOh3BrePPZjUvaK7hsnAKsNpFKHrFFvTrcLHpEEcN_hdoH_7EupnirMm3RbYSws7LkPpTnFMSyvOPOoO_HyyWvXyQLg Dec 30 11:17:40 volumio volumio[18081]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=info msg="zeroconf server listening on port 40841" Dec 30 11:17:40 volumio sudo[18500]: 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 Dec 30 11:17:40 volumio sudo[18500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:40 volumio sudo[18500]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:40 volumio volumio[18081]: info: Starting Shairport Sync Dec 30 11:17:40 volumio volumio[18081]: info: Starting Shairport Sync Dec 30 11:17:40 volumio volumio[18081]: info: Starting Shairport Sync Dec 30 11:17:40 volumio sudo[18517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:40 volumio sudo[18517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=debug msg="obtained new client token: AABu3wJTm6UXzqHV8rJnjweCOPr5J8wkKNQQ+1JGAGSUVqNARkzrGukJQ+LPAuVPjEyWhq81FwvyhgliY/lqpS5mEjFQTeM187rhE7Ncv1vreg60/fo7+0+11T7ZSyw6IE2PO/Rh0oeb87rSNt2N+FTOwCGj9u0l0tNa7Ut8oiiLtANSsz+oiy4zXXbYL4oAwREdCUnhAJO5APZTDtmXsoiRV59H10gMIzoEGl7Tatv5Bd7XOJQlpY+3AQ==" Dec 30 11:17:40 volumio sudo[18519]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:40 volumio sudo[18519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:40 volumio sudo[18521]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:40 volumio sudo[18521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:40 volumio volumio[18081]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 11:17:40 volumio go-librespot[18488]: time="2025-12-30T11:17:40-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:17:41 volumio go-librespot[18488]: time="2025-12-30T11:17:41-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:17:41 volumio go-librespot[18488]: time="2025-12-30T11:17:41-06:00" level=debug msg="completed challenge" Dec 30 11:17:41 volumio sudo[18527]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 11:17:41 volumio sudo[18527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:41 volumio systemd[1]: shairport-sync.service: Consumed 2.058s CPU time. Dec 30 11:17:41 volumio sudo[18527]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio go-librespot[18488]: time="2025-12-30T11:17:41-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 " Dec 30 11:17:41 volumio volumio[18081]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:17:41 volumio volumio[18081]: info: Output device has changed, restarting MPD Dec 30 11:17:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:41 volumio sudo[18517]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:41 volumio sudo[18521]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio volumio[18081]: info: Output device has changed, restarting Shairport Sync Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio sudo[18534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:17:41 volumio sudo[18534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:41 volumio sudo[18519]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio sudo[18534]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio sudo[18536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:17:41 volumio sudo[18536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio volumio[18081]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:17:41 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:17:41 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:17:41 volumio systemd[1]: mpd.service: Consumed 1.661s CPU time. Dec 30 11:17:41 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:17:41 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:17:41 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:17:41 volumio volumio[18081]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 30 11:17:41 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:17:41 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:17:41 volumio sudo[18563]: 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 Dec 30 11:17:41 volumio sudo[18563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio sudo[18563]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio volumio[18081]: info: MPD Permissions set Dec 30 11:17:41 volumio volumio[18081]: info: Shairport-Sync Started Dec 30 11:17:41 volumio volumio[18081]: Error adding Membership: Error: addMembership EINVAL Dec 30 11:17:41 volumio volumio[18081]: info: Shairport-Sync Started Dec 30 11:17:41 volumio volumio[18081]: info: Shairport-Sync Started Dec 30 11:17:41 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio sudo[18567]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 11:17:41 volumio sudo[18567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:41 volumio systemd[1]: Reloading. Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:41 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:41 volumio volumio[18081]: info: Starting Shairport Sync Dec 30 11:17:41 volumio sudo[18564]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:17:41 volumio sudo[18564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:17:41 volumio sudo[18564]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:41 volumio sudo[18575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:17:41 volumio sudo[18575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:41 volumio volumio[18081]: 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"} Dec 30 11:17:41 volumio volumio[18081]: info: Spotify Successfully logged in Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:17:41 volumio volumio[18081]: info: [1767115061835] CoreMusicLibrary::Adding element Spotify Dec 30 11:17:41 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source Bandcamp Discover Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source SoundCloud Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source YouTube2 Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source YouTube Music Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source Podcast Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source Volusonic Dec 30 11:17:41 volumio volumio[18081]: Cannot find translation for source Spotify Dec 30 11:17:42 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.98.249 Dec 30 11:17:42 volumio avahi-daemon[664]: Registering new address record for 169.254.98.249 on eth0.IPv4. Dec 30 11:17:42 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:42 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.98.249 Dec 30 11:17:42 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 11:17:42 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:42 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:42 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:17:42 volumio volumio[18081]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:17:43 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.98.249 Dec 30 11:17:43 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.98.249 Dec 30 11:17:43 volumio avahi-daemon[664]: Withdrawing address record for 169.254.98.249 on eth0. Dec 30 11:17:43 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:43 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:43 volumio volumio[18081]: info: go-librespot daemon successfully initialized Dec 30 11:17:44 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. Dec 30 11:17:44 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. Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.779382, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:44 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.780284, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:44 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22895 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.780958, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:44 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.781609, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:44 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22896 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.782259, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:44 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.782924, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:44 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22897 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.783616, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:44 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.784252, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:44 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22898 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.784908, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:44 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:44 volumio nmbd[1048]: [2025/12/30 11:17:44.785543, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:44 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22899 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:44 volumio sudo[18567]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:44 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:44 volumio sudo[18628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:44 volumio sudo[18628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Dec 30 11:17:45 volumio sudo[18628]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:45 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 11:17:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:45 volumio sudo[18633]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 11:17:45 volumio sudo[18633]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:45 volumio go-librespot[18632]: go-librespot daemon starting... Dec 30 11:17:45 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:17:45 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:17:45 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:45 volumio systemd[1]: shairport-sync.service: Consumed 1.548s CPU time. Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=debug msg="app state loaded" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:45 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:45 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:45 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:45 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:17:45 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:17:45 volumio sudo[18575]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:45 volumio volumio[18081]: info: Shairport-Sync Started Dec 30 11:17:45 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 11:17:45 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-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]" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-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]" Dec 30 11:17:45 volumio sudo[18633]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=info msg="zeroconf server listening on port 42855" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-06:00" level=debug msg="obtained new client token: AACou2AX10Ldr2lqeyj+poQlHYzp96yj+1OBvX5R1x/anGmUmfDkzuhxY+O9DrDtoVOPSnRDo2SGL8Fv3jRsOABewI1VeJsqCqHOArQPE2l0Zzm8Zidmx0XyKWwueISKLFrGljAkfDvYz9SDHJ141GS140AvcKpwboMXWrh+MICRV0N9Vf27zVFQpvGvextirQZ2NDy1slofFmqTapQbtwrFfB/VVTN+VdvUV5Dv95M9by2kccNmA+c7cg==" Dec 30 11:17:45 volumio go-librespot[18635]: time="2025-12-30T11:17:45-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" Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.792875, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:45 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.795364, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:45 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22895 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.796362, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:45 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.797205, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:45 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22896 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.797918, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:45 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.798907, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:45 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22897 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.799754, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:45 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.800429, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:45 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22898 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.800578, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:45 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:45 volumio nmbd[1048]: [2025/12/30 11:17:45.800679, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:45 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22899 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:46 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:46 volumio sudo[18659]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:46 volumio sudo[18659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:46 volumio sudo[18659]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:46 volumio volumio[18081]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 11:17:46 volumio sudo[18663]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 11:17:46 volumio sudo[18663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:46 volumio sudo[18663]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:46 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 11:17:46 volumio sudo[18666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 11:17:46 volumio sudo[18666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:46 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:17:46 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:17:46 volumio sudo[18666]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:46 volumio volumio[18081]: info: Initializing connection to go-librespot Websocket Dec 30 11:17:46 volumio go-librespot[18635]: time="2025-12-30T11:17:46-06:00" level=debug msg="new websocket client" Dec 30 11:17:46 volumio volumio[18081]: info: Connection to go-librespot Websocket established Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803074, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:46 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803306, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:46 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22895 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803405, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:46 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803481, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:46 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22896 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803561, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:46 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803636, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:46 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22897 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803708, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:46 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803781, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:46 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22898 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803876, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Dec 30 11:17:46 volumio nmbd[1048]: Packet send failed to 169.254.255.255(137) ERRNO=Network is unreachable Dec 30 11:17:46 volumio nmbd[1048]: [2025/12/30 11:17:46.803948, 0] ../../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Dec 30 11:17:46 volumio nmbd[1048]: retransmit_or_expire_response_records: Failed to resend packet id 22899 to IP 169.254.255.255 on subnet 169.254.98.249 Dec 30 11:17:47 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:47 volumio sudo[18673]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:47 volumio sudo[18673]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:47 volumio sudo[18673]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:47 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:47 volumio sudo[18676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:47 volumio sudo[18676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:47 volumio sudo[18676]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio mpd[18626]: 2025-12-30T11:17:48 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 11:17:48 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:48 volumio sudo[18679]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:48 volumio sudo[18679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:48 volumio sudo[18679]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.4.124 Dec 30 11:17:48 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:48 volumio avahi-daemon[664]: Registering new address record for 169.254.4.124 on eth0.IPv4. Dec 30 11:17:48 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 11:17:48 volumio sudo[18423]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio sudo[18439]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio sudo[18536]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:48 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:48 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:48 volumio volumio[18081]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:17:48 volumio volumio[18081]: assert.ok(self.idling) Dec 30 11:17:48 volumio volumio[18081]: error: The expression evaluated to a falsy value: Dec 30 11:17:48 volumio volumio[18081]: assert.ok(self.idling) Dec 30 11:17:48 volumio volumio[18081]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:17:48 volumio volumio[18081]: assert.ok(self.idling) Dec 30 11:17:48 volumio volumio[18081]: error: The expression evaluated to a falsy value: Dec 30 11:17:48 volumio volumio[18081]: assert.ok(self.idling) Dec 30 11:17:48 volumio volumio[18081]: info: MPD running with PID18626 Dec 30 11:17:48 volumio volumio[18081]: ,establishing connection Dec 30 11:17:48 volumio volumio[18081]: error: updateQueue error: null Dec 30 11:17:48 volumio volumio[18081]: error: updateQueue error: null Dec 30 11:17:48 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.4.124 Dec 30 11:17:48 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.4.124 Dec 30 11:17:48 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.4.124 Dec 30 11:17:48 volumio avahi-daemon[664]: Withdrawing address record for 169.254.4.124 on eth0. Dec 30 11:17:48 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:48 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:48 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:48 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:48 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:48 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 11:17:48 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:48 volumio sudo[18719]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:48 volumio sudo[18719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:48 volumio sudo[18719]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:48 volumio volumio-remote-updater[702]: [2025-12-30 11:17:48] [connect] Successful connection Dec 30 11:17:48 volumio volumio-remote-updater[702]: [2025-12-30 11:17:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767115068 101 Dec 30 11:17:48 volumio volumio[18081]: 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 Dec 30 11:17:49 volumio volumio[18081]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:17:49 volumio sudo[18722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:17:49 volumio sudo[18722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:49 volumio sudo[18722]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:49 volumio volumio[18081]: info: Completed starting Core Plugins Dec 30 11:17:49 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:49 volumio volumio[18081]: info: ----- MyVolumio plugins startup ---- Dec 30 11:17:49 volumio volumio[18081]: info: ------------------------------------------- Dec 30 11:17:49 volumio volumio[18081]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 11:17:49 volumio volumio[18081]: info: Getting Spotify volume Dec 30 11:17:49 volumio volumio[18081]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 30 11:17:49 volumio volumio[18081]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:49 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:49 volumio volumio[18081]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 30 11:17:49 volumio volumio[18081]: SPOTIFY: SPOTIFY VOLUME undefined Dec 30 11:17:49 volumio volumio[18081]: SPOTIFY: VOLUMIO VOLUME 100 Dec 30 11:17:49 volumio volumio[18081]: info: Aligning Spotify Volume to Volumio Volume Dec 30 11:17:49 volumio volumio[18081]: info: CoreCommandRouter::volumioGetState Dec 30 11:17:49 volumio volumio[18081]: info: CorePlayQueue::getTrack 0 Dec 30 11:17:49 volumio volumio[18081]: info: Setting Spotify Volume from Volumio: 100 Dec 30 11:17:50 volumio go-librespot[18635]: time="2025-12-30T11:17:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 30 11:17:50 volumio go-librespot[18635]: time="2025-12-30T11:17:50-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:50 volumio go-librespot[18635]: time="2025-12-30T11:17:50-06:00" level=debug msg="completed challenge" Dec 30 11:17:50 volumio go-librespot[18635]: time="2025-12-30T11:17:50-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 " Dec 30 11:17:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:50 volumio volumio[18081]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:17:50 volumio volumio[18081]: Error: socket hang up Dec 30 11:17:50 volumio volumio[18081]: at connResetException (node:internal/errors:720:14) Dec 30 11:17:50 volumio volumio[18081]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 30 11:17:50 volumio volumio[18081]: at Socket.emit (node:events:526:35) Dec 30 11:17:50 volumio volumio[18081]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 30 11:17:50 volumio volumio[18081]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 30 11:17:50 volumio volumio[18081]: code: 'ECONNRESET', Dec 30 11:17:50 volumio volumio[18081]: response: undefined Dec 30 11:17:50 volumio volumio[18081]: } Dec 30 11:17:50 volumio volumio[18081]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:17:51 volumio sudo[18752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 11:16' Dec 30 11:17:51 volumio sudo[18752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:52 volumio sudo[18752]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:52 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.179.125 Dec 30 11:17:52 volumio avahi-daemon[664]: Registering new address record for 169.254.179.125 on eth0.IPv4. Dec 30 11:17:52 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:52 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:52 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:52 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:53 volumio volumio-remote-updater[702]: [2025-12-30 11:17:52] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 11:17:53 volumio volumio-remote-updater[702]: [2025-12-30 11:17:52] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 11:17:53 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:53 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 11:17:53 volumio systemd[1]: volumio.service: Consumed 45.628s CPU time. Dec 30 11:17:53 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 11:17:53 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 11:17:53 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 743. Dec 30 11:17:53 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 11:17:53 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 11:17:53 volumio systemd[1]: volumio.service: Consumed 45.628s CPU time. Dec 30 11:17:53 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 11:17:53 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 11:17:53 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.179.125 Dec 30 11:17:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Dec 30 11:17:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:53 volumio go-librespot[18798]: go-librespot daemon starting... Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="app state loaded" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:54 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.179.125 Dec 30 11:17:54 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.179.125 Dec 30 11:17:54 volumio avahi-daemon[664]: Withdrawing address record for 169.254.179.125 on eth0. Dec 30 11:17:54 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:54 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:54 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:54 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:54 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-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]" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-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]" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-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]" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=info msg="zeroconf server listening on port 35161" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="obtained new client token: AADb4y+xVHF7uaLG0tcninJ9TYhD8dxF2ZW4MsL3tSnP39PhB4Psrd8Oc4pfEFnFLgI3vd0jitefZ1Wt1VpCzXpyza5sKXSnPWLPOGRs5pz/++fD9mt640+xf0yJSMCFfIRVL3iQO+V7kL4SZJi2NLDHC4zbEcNUxl0Snlx0MiMgjV/s35ZAMACBF3wIZ+AWmK+KGc5t/UQNeXeLZCb0YLZ68dR8itZHWueEv4OK8uRat7dsIWo2rnwVQg==" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-06:00" level=debug msg="completed challenge" Dec 30 11:17:54 volumio go-librespot[18799]: time="2025-12-30T11:17:54-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 " Dec 30 11:17:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:55 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:17:55 volumio volumio[18783]: info: ----- Volumio3 ---- Dec 30 11:17:55 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:17:55 volumio volumio[18783]: info: ----- System startup ---- Dec 30 11:17:55 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:17:56 volumio volumio[18783]: info: MYVOLUMIO Environment detected Dec 30 11:17:56 volumio volumio[18783]: info: Plugin folders cleanup Dec 30 11:17:56 volumio volumio[18783]: info: Scanning into folder /volumio/app/plugins/ Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category audio_interface Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category miscellanea Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category music_service Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category plugins.json Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category system_controller Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category user_interface Dec 30 11:17:56 volumio volumio[18783]: info: Scanning into folder /data/plugins/ Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category audio_interface Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category music_service Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category system_controller Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category system_hardware Dec 30 11:17:56 volumio volumio[18783]: info: Scanning category user_interface Dec 30 11:17:56 volumio volumio[18783]: info: Plugin folders cleanup completed Dec 30 11:17:56 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:17:56 volumio volumio[18783]: info: ----- Core plugins startup ---- Dec 30 11:17:56 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:17:56 volumio volumio[18783]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 11:17:56 volumio volumio[18783]: info: Adding plugin upnp to MyMusic Plugins Dec 30 11:17:56 volumio volumio[18783]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 11:17:56 volumio volumio[18783]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 11:17:56 volumio volumio[18783]: info: Loading plugins from folder /data/plugins/ Dec 30 11:17:56 volumio volumio[18783]: info: Loading plugin "system"... Dec 30 11:17:56 volumio volumio[18783]: info: Loading plugin "appearance"... Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "network"... Dec 30 11:17:57 volumio volumio[18783]: info: Refreshing Cached IP Addresses Dec 30 11:17:57 volumio sudo[18839]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:17:57 volumio sudo[18839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:57 volumio sudo[18841]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:17:57 volumio sudo[18841]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "services"... Dec 30 11:17:57 volumio sudo[18839]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "alsa_controller"... Dec 30 11:17:57 volumio sudo[18841]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:57 volumio sudo[18849]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 11:17:57 volumio sudo[18849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:57 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "wizard"... Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "networkfs"... Dec 30 11:17:57 volumio volumio[18783]: info: Starting Udev Watcher for removable devices Dec 30 11:17:57 volumio volumio[18783]: info: Ignoring mount for partition: boot Dec 30 11:17:57 volumio volumio[18783]: info: Ignoring mount for partition: volumio Dec 30 11:17:57 volumio volumio[18783]: info: Ignoring mount for partition: volumio_data Dec 30 11:17:57 volumio volumio[18783]: info: Mounting Device Wikipedia Dec 30 11:17:57 volumio sudo[18878]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 11:17:57 volumio sudo[18878]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:17:57 volumio sudo[18878]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:57 volumio volumio[18783]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 11:17:57 volumio volumio[18783]: dmesg(1) may have more information after failed mount system call. Dec 30 11:17:57 volumio volumio[18783]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 11:17:57 volumio volumio[18783]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 11:17:57 volumio volumio[18783]: dmesg(1) may have more information after failed mount system call. Dec 30 11:17:57 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "volumio_command_line_client"... Dec 30 11:17:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Dec 30 11:17:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "upnp"... Dec 30 11:17:57 volumio volumio[18783]: info: [1767115077720] Starting Upmpd Daemon Dec 30 11:17:57 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "my_music"... Dec 30 11:17:57 volumio volumio[18783]: info: Loading plugin "mpd"... Dec 30 11:17:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:17:57 volumio go-librespot[18880]: go-librespot daemon starting... Dec 30 11:17:57 volumio go-librespot[18881]: time="2025-12-30T11:17:57-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:17:57 volumio go-librespot[18881]: time="2025-12-30T11:17:57-06:00" level=debug msg="app state loaded" Dec 30 11:17:57 volumio go-librespot[18881]: time="2025-12-30T11:17:57-06:00" level=debug msg="stored credentials not found" Dec 30 11:17:57 volumio go-librespot[18881]: time="2025-12-30T11:17:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:17:58 volumio sudo[18849]: pam_unix(sudo:session): session closed for user root Dec 30 11:17:58 volumio volumio-remote-updater[702]: [2025-12-30 11:17:58] [connect] Successful connection Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-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]" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-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]" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-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]" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-06:00" level=info msg="zeroconf server listening on port 46013" Dec 30 11:17:58 volumio volumio[18783]: info: Loading plugin "upnp_browser"... Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-06:00" level=debug msg="obtained new client token: AADv9Cb7CBVJQGozgMbTbK44exILxOXXBwMn21a0bdOJXAJ5/nPr/papH1DOo22tLySx1mGm7iFcwNP1gYsnwVk+E/X0ufsAUuNoU2aaY/NVtbSlxK+p0CnXKxU0Yuk+Y8E5zmXMG1PCgveKsPVCTPa0k7REqywa5gCce6dAbgpoCXjqF6O4CqC9KX7UlVg4eJb3IrGClTbXI4H9fIQ0aJlfWUhebgJXTaDL1r/MXyYH/s8GI6GWQLMLJg==" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-06:00" level=debug msg="completed keyexchange" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-06:00" level=debug msg="completed challenge" Dec 30 11:17:58 volumio go-librespot[18881]: time="2025-12-30T11:17:58-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 " Dec 30 11:17:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:17:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:17:58 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.75.18 Dec 30 11:17:58 volumio avahi-daemon[664]: Registering new address record for 169.254.75.18 on eth0.IPv4. Dec 30 11:17:58 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:17:58 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:58 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:58 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.18 Dec 30 11:17:59 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 11:17:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.18 Dec 30 11:17:59 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.75.18 Dec 30 11:17:59 volumio avahi-daemon[664]: Withdrawing address record for 169.254.75.18 on eth0. Dec 30 11:17:59 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:17:59 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:17:59 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:17:59 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:17:59 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "alarm-clock"... Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "airplay_emulation"... Dec 30 11:18:01 volumio volumio[18783]: info: Starting Shairport Sync Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "last_100"... Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "webradio"... Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "i2s_dacs"... Dec 30 11:18:01 volumio volumio[18783]: info: I2S DAC not set, start Auto-detection Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "volumiodiscovery"... Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** For more information see Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:18:01 volumio volumio[18783]: *** WARNING *** For more information see Dec 30 11:18:01 volumio node[18783]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 11:18:01 volumio node[18783]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:18:01 volumio node[18783]: *** WARNING *** For more information see Dec 30 11:18:01 volumio node[18783]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 11:18:01 volumio node[18783]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 11:18:01 volumio node[18783]: *** WARNING *** For more information see Dec 30 11:18:01 volumio volumio[18783]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 11:18:01 volumio volumio[18783]: info: Discovery: Started advertising with name: Volumio Dec 30 11:18:01 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 11:18:01 volumio volumio[18783]: info: Loading plugin "bandcamp"... Dec 30 11:18:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Dec 30 11:18:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:01 volumio go-librespot[18924]: go-librespot daemon starting... Dec 30 11:18:01 volumio go-librespot[18925]: time="2025-12-30T11:18:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:01 volumio go-librespot[18925]: time="2025-12-30T11:18:01-06:00" level=debug msg="app state loaded" Dec 30 11:18:01 volumio go-librespot[18925]: time="2025-12-30T11:18:01-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:01 volumio go-librespot[18925]: time="2025-12-30T11:18:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-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]" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-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]" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-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]" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-06:00" level=info msg="zeroconf server listening on port 43931" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-06:00" level=debug msg="obtained new client token: AABVJPTWlbhQ9QMNi8n5O154/j3GlsvxMllBsHfzTbMraOQJlBMEr0xCWXe87aa5wcAWhHdL4AGY6Bt+qGIPQ09IyDHrgXlsd/zTpiYMx/49rx+ybU7xxyiC81QP/VlogvDu016EbxQdP9KdQSkUZVvE8Hdna31S0u/vIWtrlMfgqZwf5XafM5fKRZ1s1iFd88EWG71Zxk4TpVZ9J2fX51MnEvWdFoA+kRHOkIEReyY3FEbChqP8PRc=" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-06:00" level=debug msg="completed challenge" Dec 30 11:18:02 volumio go-librespot[18925]: time="2025-12-30T11:18:02-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 " Dec 30 11:18:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:02 volumio volumio[18783]: info: Plugin calmradio is not enabled Dec 30 11:18:02 volumio volumio[18783]: info: Loading plugin "soundcloud"... Dec 30 11:18:03 volumio volumio[18783]: info: Loading plugin "spop"... Dec 30 11:18:03 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 11:18:04 volumio volumio[18783]: info: Loading plugin "squeezelite_mc"... Dec 30 11:18:04 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.47.194 Dec 30 11:18:04 volumio avahi-daemon[664]: Registering new address record for 169.254.47.194 on eth0.IPv4. Dec 30 11:18:04 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:18:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:04 volumio volumio[18783]: info: Loading plugin "youtube2"... Dec 30 11:18:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.47.194 Dec 30 11:18:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.47.194 Dec 30 11:18:05 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.47.194 Dec 30 11:18:05 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:18:05 volumio avahi-daemon[664]: Withdrawing address record for 169.254.47.194 on eth0. Dec 30 11:18:05 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:05 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:05 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:05 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:18:05 volumio volumio[18783]: info: Loading plugin "ytcr"... Dec 30 11:18:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Dec 30 11:18:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:05 volumio go-librespot[18965]: go-librespot daemon starting... Dec 30 11:18:05 volumio go-librespot[18966]: time="2025-12-30T11:18:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:05 volumio go-librespot[18966]: time="2025-12-30T11:18:05-06:00" level=debug msg="app state loaded" Dec 30 11:18:05 volumio go-librespot[18966]: time="2025-12-30T11:18:05-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:05 volumio go-librespot[18966]: time="2025-12-30T11:18:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18: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]" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18: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]" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18: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]" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18:06-06:00" level=info msg="zeroconf server listening on port 34237" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18:06-06:00" level=debug msg="obtained new client token: AACgRNCLRpor3UXmd7B+5Fx3al3S1FWiShP8hYhEFXoBLfGFVIrHwQfXh8OTAckyr9V5GYHr4sJxov24NQi130Vtkg146C0QO47SgHYwQ/zasIEmGq7meplJp0sJAqlLtK+iKITT0dLjGH+9XdwQY+G+OxQYZUZaJ42EVQjWldUZLiTXpTsFzLgi/PXGWfqvuFkBlZEZSl5cNv7vvuCkbu4AzPRlRUg+BkDLPKm73FStYCNA80MkCjTPQw==" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18:06-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18:06-06:00" level=debug msg="completed challenge" Dec 30 11:18:06 volumio go-librespot[18966]: time="2025-12-30T11:18: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 " Dec 30 11:18:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:07 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 11:18:08 volumio volumio[18783]: info: Loading plugin "ytmusic"... Dec 30 11:18:08 volumio volumio[18783]: info: Plugin now_playing is not enabled Dec 30 11:18:08 volumio volumio[18783]: info: Loading plugin "outputs"... Dec 30 11:18:08 volumio volumio[18783]: info: Loading plugin "albumart"... Dec 30 11:18:08 volumio volumio[18783]: info: Plugin example_plugin is not enabled Dec 30 11:18:08 volumio volumio[18783]: info: Loading plugin "inputs"... Dec 30 11:18:08 volumio volumio[18783]: info: Loading plugin "updater_comm"... Dec 30 11:18:09 volumio volumio[18783]: info: Plugin mpdemulation is not enabled Dec 30 11:18:09 volumio volumio[18783]: info: Loading plugin "rest_api"... Dec 30 11:18:09 volumio volumio[18783]: info: Loading plugin "websocket"... Dec 30 11:18:09 volumio volumio[18783]: info: Starting Socket.io Server version 1.7.4 Dec 30 11:18:09 volumio volumio[18783]: info: Plugin fusiondsp is not enabled Dec 30 11:18:09 volumio volumio[18783]: info: Plugin mpdoutput is not enabled Dec 30 11:18:09 volumio volumio[18783]: info: Plugin RoonBridge is not enabled Dec 30 11:18:09 volumio volumio[18783]: info: Loading plugin "podcast"... Dec 30 11:18:09 volumio volumio[18783]: info: ControllerPodcast::constructor Dec 30 11:18:09 volumio volumio[18783]: info: Loading plugin "volusonic"... Dec 30 11:18:09 volumio volumio[18990]: Forking 3 albumart workers Dec 30 11:18:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Dec 30 11:18:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:09 volumio go-librespot[19030]: go-librespot daemon starting... Dec 30 11:18:09 volumio go-librespot[19031]: time="2025-12-30T11:18:09-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:09 volumio go-librespot[19031]: time="2025-12-30T11:18:09-06:00" level=debug msg="app state loaded" Dec 30 11:18:09 volumio go-librespot[19031]: time="2025-12-30T11:18:09-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:09 volumio go-librespot[19031]: time="2025-12-30T11:18:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:10 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.244.152 Dec 30 11:18:10 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:18:10 volumio avahi-daemon[664]: Registering new address record for 169.254.244.152 on eth0.IPv4. Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-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]" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-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]" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-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]" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-06:00" level=info msg="zeroconf server listening on port 40735" Dec 30 11:18:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-06:00" level=debug msg="obtained new client token: AADOqMraC/mx36ooMQFt058/rMvRkQmrMVQ/mmi+T8KuMUDmbKdcu901xUlxSJJX7Zu1pwepXmu68t+tVLjLWjb8Kfrj8/A06koYUPdHBRXk9htHryb6VCGHcn1qIS01NRkySWlOzh6uXBDpgCoGAvBImEEVJ+JouyRJppc4UpZGYhnFhCtoAH99jbMc2VpyIy3azhHoFh/lKfedgDEgV84rkH3f/9Ya/QOsebLXzr0hcHoahtzmHuwxkA==" Dec 30 11:18:10 volumio volumio-remote-updater[702]: [2025-12-30 11:18:10] [connect] Successful connection Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18:10-06:00" level=debug msg="completed challenge" Dec 30 11:18:10 volumio go-librespot[19031]: time="2025-12-30T11:18: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 " Dec 30 11:18:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.244.152 Dec 30 11:18:11 volumio ntpd[872]: IO: Listen normally on 489 eth0 169.254.244.152:123 Dec 30 11:18:11 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Dec 30 11:18:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.244.152 Dec 30 11:18:11 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.244.152 Dec 30 11:18:11 volumio avahi-daemon[664]: Withdrawing address record for 169.254.244.152 on eth0. Dec 30 11:18:11 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:18:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:11 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:18:12 volumio volumio[18783]: info: Applying required configuration parameters for plugin volusonic Dec 30 11:18:12 volumio volumio[18783]: info: Loading plugin "backup_restore"... Dec 30 11:18:12 volumio volumio[19002]: Starting albumart workers Dec 30 11:18:12 volumio volumio[19000]: Starting albumart workers Dec 30 11:18:12 volumio volumio[19001]: Starting albumart workers Dec 30 11:18:12 volumio volumio[18783]: info: Applying required configuration parameters for plugin backup_restore Dec 30 11:18:12 volumio volumio[18783]: info: Plugin rpi_eeprom_config is not enabled Dec 30 11:18:12 volumio volumio[18783]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 11:18:12 volumio volumio[18783]: info: Loading plugin "scheduledrestart"... Dec 30 11:18:12 volumio volumio[18783]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 11:18:12 volumio volumio[18783]: info: Plugin Bluetoothremote is not enabled Dec 30 11:18:12 volumio volumio[18783]: info: Plugin music_services_shield is not enabled Dec 30 11:18:12 volumio volumio[18783]: info: Loading plugin "Systeminfo"... Dec 30 11:18:13 volumio ntpd[872]: IO: Deleting interface #489 eth0, 169.254.244.152#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Dec 30 11:18:13 volumio volumio[18783]: info: Plugin peppymeterbasic is not enabled Dec 30 11:18:13 volumio volumio[18783]: info: Loading plugin "peppyspectrum"... Dec 30 11:18:13 volumio volumio[18783]: info: Loading i18n strings for locale en Dec 30 11:18:13 volumio volumio[18783]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 11:18:13 volumio volumio[18783]: Updating browse sources language Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Dec 30 11:18:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::initPlayerControls Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:18:13 volumio volumio[18783]: Express server listening on port 3000 Dec 30 11:18:13 volumio volumio[18783]: [Metrics] WebUI: 19s 202.23ms Dec 30 11:18:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:14 volumio go-librespot[19089]: go-librespot daemon starting... Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::resetVolumioState Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::getcurrentVolume Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="app state loaded" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:14 volumio sudo[19101]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 11:18:14 volumio sudo[19101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio sudo[19103]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 11:18:14 volumio sudo[19101]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:14 volumio sudo[19103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio sudo[19103]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:14 volumio volumio[18783]: info: Volumio Network Manager: Network status updated: 1 Dec 30 11:18:14 volumio volumio-remote-updater[702]: [2025-12-30 11:18:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767115090 101 Dec 30 11:18:14 volumio volumio[18783]: 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 Dec 30 11:18:14 volumio volumio[18783]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::pushState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioPushState Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::updateTrackBlock Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrackBlock Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-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]" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-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]" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-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]" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=info msg="zeroconf server listening on port 45723" Dec 30 11:18:14 volumio volumio[18783]: info: Reloading queue from file Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::setRepeat null single undefined Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::pushState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioPushState Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::setRandom null Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::pushState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioPushState Dec 30 11:18:14 volumio volumio[18783]: info: Setting Device type: Raspberry PI Dec 30 11:18:14 volumio volumio[18783]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:18:14 volumio volumio[18783]: info: CoreStateMachine::pushState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioPushState Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="obtained new client token: AACSp8oux7MFJ2zlQrdMK7UbKSJZMQXArR8N56F49FeDiY8O8b2/zNUWLfwd7BR0OCxpbME5KHH8ienkgiTUcnXjphXz96+PDES5DW5EgA4tPnGTHrHSQXIvdbPiN1LZVOjsQH/ElxrrNHgO3htM6kUHg+x19OhIU0BUUUKWhTCuGnEeaz7EkLso8t1QAYLEbXZjyhLhEdFozmSbl9Iy7Y5vEbrJ8ZkVboSA+PkGX3N02PTUVzfybx9/4A==" Dec 30 11:18:14 volumio sudo[19117]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 11:18:14 volumio sudo[19117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio volumio[18783]: info: Completed loading Core Plugins Dec 30 11:18:14 volumio volumio[18783]: info: Preparing to generate the ALSA configuration file Dec 30 11:18:14 volumio volumio[18783]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:18:14 volumio volumio[18783]: info: Discovery: Found device Volumio Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioGetState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio sudo[19117]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:14 volumio volumio[18783]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 11:18:14 volumio volumio[18783]: info: Discovery: Found device Volumio Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioGetState Dec 30 11:18:14 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:14 volumio volumio[18783]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:18:14 volumio volumio[18783]: info: Reading ALSA contributions from plugins. Dec 30 11:18:14 volumio volumio[18783]: info: Upmpdcli Daemon Started Dec 30 11:18:14 volumio volumio[18783]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:18:14 volumio volumio[18783]: info: Output device has changed, restarting MPD Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-06:00" level=debug msg="completed challenge" Dec 30 11:18:14 volumio volumio[18783]: info: Output device has changed, restarting Shairport Sync Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:14 volumio sudo[19123]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:18:14 volumio sudo[19123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio sudo[19123]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:14 volumio sudo[19125]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:18:14 volumio sudo[19125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio volumio[18783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:18:14 volumio volumio[18783]: info: ___________ START PLUGINS ___________ Dec 30 11:18:14 volumio volumio[18783]: info: ControllerMpd::onStart: Initializing MPD Dec 30 11:18:14 volumio volumio[18783]: info: Creating MPD Configuration file Dec 30 11:18:14 volumio go-librespot[19091]: time="2025-12-30T11:18:14-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 " Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:14 volumio volumio[18783]: info: [1767115094640] CoreMusicLibrary::Adding element Media Servers Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:14 volumio sudo[19133]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:18:14 volumio sudo[19133]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 11:18:14 volumio sudo[19133]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:14 volumio sudo[19135]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:18:14 volumio sudo[19135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:14 volumio volumio[18783]: info: [1767115094761] CoreMusicLibrary::Adding element Last_100 Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:14 volumio volumio[18783]: info: [1767115094772] CoreMusicLibrary::Adding element Webradio Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:14 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:18:14 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:18:14 volumio systemd[1]: mpd.service: Consumed 3.719s CPU time. Dec 30 11:18:14 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:18:14 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:18:14 volumio volumio[18783]: info: Initializing BBC Radios Dec 30 11:18:14 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:14 volumio volumio[18783]: info: [1767115094866] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:14 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:14 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:14 volumio volumio[18783]: info: [1767115094890] CoreMusicLibrary::Adding element SoundCloud Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:14 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:18:14 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:14 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:14 volumio volumio[18783]: info: Creating Spotify config file Dec 30 11:18:14 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:15 volumio sudo[19160]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:18:15 volumio sudo[19160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:18:15 volumio sudo[19160]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:15 volumio volumio[18783]: info: [squeezelite_mc] Starting proxy server... Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:15 volumio volumio[18783]: info: [1767115095566] CoreMusicLibrary::Adding element YouTube2 Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:15 volumio volumio[18783]: info: [1767115095597] CoreMusicLibrary::Adding element YouTube Music Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:15 volumio volumio[18783]: info: [1767115095616] CoreMusicLibrary::Adding element Podcast Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Podcast Dec 30 11:18:15 volumio volumio[18783]: info: Loading i18n strings for locale en Dec 30 11:18:15 volumio volumio[18783]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 11:18:15 volumio volumio[18783]: Updating browse sources language Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Podcast Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Podcast Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:15 volumio volumio[18783]: info: [1767115095698] CoreMusicLibrary::Adding element Volusonic Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Podcast Dec 30 11:18:15 volumio volumio[18783]: Cannot find translation for source Volusonic Dec 30 11:18:15 volumio volumio[18783]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 11:18:15 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 11:18:15 volumio volumio[18783]: info: Volumio Calling Home Dec 30 11:18:15 volumio volumio[18783]: info: [squeezelite_mc] Proxy server started on port 36479 Dec 30 11:18:15 volumio volumio[18783]: info: Preparing to generate the ALSA configuration file Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 11:18:16 volumio volumio[18783]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 11:18:16 volumio volumio[18783]: info: Reading ALSA contributions from plugins. Dec 30 11:18:16 volumio volumio[18783]: info: MPD Permissions set Dec 30 11:18:16 volumio volumio[18783]: info: MPD Permissions set Dec 30 11:18:16 volumio volumio[18783]: info: Volumio called home Dec 30 11:18:16 volumio volumio[18783]: info: Spotify config file written Dec 30 11:18:16 volumio sudo[19169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 11:18:16 volumio sudo[19169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:16 volumio volumio[18783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 30 11:18:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:16 volumio volumio[18783]: info: VolumeController:: Volume=100 Mute =false Dec 30 11:18:16 volumio volumio[18783]: info: CoreStateMachine::pushState Dec 30 11:18:16 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::volumioPushState Dec 30 11:18:16 volumio volumio[18783]: info: [squeezelite_mc] Server discovery started Dec 30 11:18:16 volumio volumio[18783]: info: [squeezelite_mc] Player finder started Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 11:18:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:16 volumio go-librespot[19171]: go-librespot daemon starting... Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio sudo[19169]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio go-librespot[19173]: time="2025-12-30T11:18:16-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:16 volumio go-librespot[19173]: time="2025-12-30T11:18:16-06:00" level=debug msg="app state loaded" Dec 30 11:18:16 volumio go-librespot[19173]: time="2025-12-30T11:18:16-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:16 volumio go-librespot[19173]: time="2025-12-30T11:18:16-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:16 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.174.19 Dec 30 11:18:16 volumio avahi-daemon[664]: Registering new address record for 169.254.174.19 on eth0.IPv4. Dec 30 11:18:16 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:16 volumio volumio[18783]: info: No need to fix Spotify hosts Dec 30 11:18:16 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:16 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:16 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.174.19 Dec 30 11:18:16 volumio volumio[18783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 30 11:18:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.174.19 Dec 30 11:18:17 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.174.19 Dec 30 11:18:17 volumio avahi-daemon[664]: Withdrawing address record for 169.254.174.19 on eth0. Dec 30 11:18:17 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18: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]" Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18: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]" Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18: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]" Dec 30 11:18:17 volumio volumio[18783]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 11:18:17 volumio volumio[18783]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18:17-06:00" level=info msg="zeroconf server listening on port 33897" Dec 30 11:18:17 volumio volumio[18783]: 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 Dec 30 11:18:17 volumio volumio[18783]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:18:17 volumio volumio[18783]: SPOTIFY: BQAh1rMg9XIvC2yFeRYX4kV2F58k_jLFobKiqVmxCBfRKfsB-mNuh9jo_3YiN8zzejjCteUnEyIpoAqwwy76szLD0wjzXaX-_v5q0518I2QHicdE3DGCVNd7M49GK0F6HfL4tBbc6X_O5BokpraTTilYrBkjcOJSiKgR4pq-1OqfYo9YZ3EXbE_a05lOuJ70VF6rIGoYLwVNuSWmRyezdENypzDRzx7ICdZmOMs Dec 30 11:18:17 volumio volumio[18783]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 11:18:17 volumio volumio[18783]: info: New Spotify access token = BQAh1rMg9XIvC2yFeRYX4kV2F58k_jLFobKiqVmxCBfRKfsB-mNuh9jo_3YiN8zzejjCteUnEyIpoAqwwy76szLD0wjzXaX-_v5q0518I2QHicdE3DGCVNd7M49GK0F6HfL4tBbc6X_O5BokpraTTilYrBkjcOJSiKgR4pq-1OqfYo9YZ3EXbE_a05lOuJ70VF6rIGoYLwVNuSWmRyezdENypzDRzx7ICdZmOMs Dec 30 11:18:17 volumio volumio[18783]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 11:18:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:17 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:18:17 volumio sudo[19220]: 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 Dec 30 11:18:17 volumio sudo[19220]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio sudo[19220]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18:17-06:00" level=debug msg="obtained new client token: AADzXcz5DW/bdTOAT8JfXEtm2g3knNLzlLNTWKCaOoRYmD8VAKx6bawg95V8ZJBKvN2+ZJdoQd5tWB7z/vEXr355UpjjX6FGgpWVTTLJQW9fX8dewLj12zUEv3B2yW4301fF7SJRwvtwCDqVDST/krt4ZGoPEDRxtdIK0eIgQmevdIGeGC18/2GT5MHPJPK5YlOeHuQUhokhyCHnNyTRSMwIDjVaHYADkDs0fVkwsIQQCoTPEvKfDp4=" Dec 30 11:18:17 volumio volumio[18783]: info: Starting Shairport Sync Dec 30 11:18:17 volumio volumio[18783]: info: Starting Shairport Sync Dec 30 11:18:17 volumio volumio[18783]: info: Starting Shairport Sync Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:17 volumio sudo[19230]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:18:17 volumio sudo[19230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio sudo[19232]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:18:17 volumio sudo[19232]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18:17-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18:17-06:00" level=debug msg="completed challenge" Dec 30 11:18:17 volumio sudo[19235]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:18:17 volumio sudo[19235]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio go-librespot[19173]: time="2025-12-30T11:18: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 " Dec 30 11:18:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:17 volumio volumio[18783]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 11:18:17 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:18:17 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:18:17 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:18:17 volumio systemd[1]: shairport-sync.service: Consumed 2.039s CPU time. Dec 30 11:18:17 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:18:17 volumio sudo[19230]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio sudo[19235]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio sudo[19232]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio sudo[19253]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 11:18:17 volumio sudo[19253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio volumio[18783]: info: Asound.conf file unchanged, so no further update is needed Dec 30 11:18:17 volumio volumio[18783]: info: Output device has changed, restarting MPD Dec 30 11:18:17 volumio sudo[19253]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio volumio[18783]: info: Output device has changed, restarting Shairport Sync Dec 30 11:18:17 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:17 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:17 volumio sudo[19259]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 11:18:17 volumio sudo[19259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio sudo[19259]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:17 volumio sudo[19262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 11:18:17 volumio sudo[19262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:17 volumio volumio[18783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 11:18:18 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 11:18:18 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 11:18:18 volumio systemd[1]: mpd.service: Consumed 2.912s CPU time. Dec 30 11:18:18 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 11:18:18 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 11:18:18 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 11:18:18 volumio volumio[18783]: info: PeppySpectrum ---peppyspectrum status stop Dec 30 11:18:18 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 11:18:18 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 11:18:18 volumio sudo[19287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 30 11:18:18 volumio volumio[18783]: info: Shairport-Sync Started Dec 30 11:18:18 volumio sudo[19287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:18 volumio volumio[18783]: Error adding Membership: Error: addMembership EINVAL Dec 30 11:18:18 volumio volumio[18783]: info: Shairport-Sync Started Dec 30 11:18:18 volumio volumio[18783]: info: Shairport-Sync Started Dec 30 11:18:18 volumio sudo[19287]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:18 volumio volumio[18783]: info: MPD Permissions set Dec 30 11:18:18 volumio volumio[18783]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 30 11:18:18 volumio sudo[19292]: 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 Dec 30 11:18:18 volumio sudo[19292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:18 volumio sudo[19292]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:18 volumio volumio[18783]: info: peppyspectrum Daemon Stop Dec 30 11:18:18 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:18 volumio sudo[19295]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 11:18:18 volumio sudo[19295]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:18 volumio systemd[1]: Reloading. Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::volumioGetState Dec 30 11:18:18 volumio volumio[18783]: info: CorePlayQueue::getTrack 0 Dec 30 11:18:18 volumio sudo[19288]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 11:18:18 volumio sudo[19288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 11:18:18 volumio sudo[19288]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:18 volumio volumio[18783]: 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"} Dec 30 11:18:18 volumio volumio[18783]: info: Spotify Successfully logged in Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 11:18:18 volumio volumio[18783]: info: [1767115098756] CoreMusicLibrary::Adding element Spotify Dec 30 11:18:18 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source Bandcamp Discover Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source SoundCloud Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source YouTube2 Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source YouTube Music Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source Podcast Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source Volusonic Dec 30 11:18:18 volumio volumio[18783]: Cannot find translation for source Spotify Dec 30 11:18:18 volumio volumio[18783]: info: Starting Shairport Sync Dec 30 11:18:18 volumio sudo[19304]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 11:18:18 volumio sudo[19304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:19 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:19 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:19 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 11:18:19 volumio volumio[18783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 11:18:20 volumio volumio[18783]: info: go-librespot daemon successfully initialized Dec 30 11:18:21 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. Dec 30 11:18:21 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. Dec 30 11:18:21 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.60.173 Dec 30 11:18:21 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:18:21 volumio avahi-daemon[664]: Registering new address record for 169.254.60.173 on eth0.IPv4. Dec 30 11:18:21 volumio sudo[19295]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:21 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:21 volumio sudo[19342]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:21 volumio sudo[19342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Dec 30 11:18:21 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:21 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:21 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:21 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.60.173 Dec 30 11:18:21 volumio sudo[19342]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:21 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 11:18:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:21 volumio go-librespot[19344]: go-librespot daemon starting... Dec 30 11:18:21 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 11:18:21 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 11:18:21 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:18:21 volumio systemd[1]: shairport-sync.service: Consumed 1.611s CPU time. Dec 30 11:18:21 volumio go-librespot[19346]: time="2025-12-30T11:18:21-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:21 volumio go-librespot[19346]: time="2025-12-30T11:18:21-06:00" level=debug msg="app state loaded" Dec 30 11:18:21 volumio go-librespot[19346]: time="2025-12-30T11:18:21-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:21 volumio go-librespot[19346]: time="2025-12-30T11:18:21-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:21 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 11:18:21 volumio sudo[19304]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:21 volumio sudo[19347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 11:18:21 volumio sudo[19347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:21 volumio volumio[18783]: info: Shairport-Sync Started Dec 30 11:18:21 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:18:22 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.60.173 Dec 30 11:18:22 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.60.173 Dec 30 11:18:22 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:18:22 volumio avahi-daemon[664]: Withdrawing address record for 169.254.60.173 on eth0. Dec 30 11:18:22 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:22 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:22 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:22 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:18:22 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 11:18:22 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:18:22 volumio sudo[19347]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-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]" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-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]" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-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]" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-06:00" level=info msg="zeroconf server listening on port 44877" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-06:00" level=debug msg="obtained new client token: AABeehQ1+dZSYiFHPPfCjDKO8cN+acWbXD3GB6ze4qIUPw7sW7qYqild6LJLTnGzTofpqaGNQEhwDx35d0U08628r4uNncPsVN7H5kn322r2jp2e2C8nT/GIC9gZzo7WDBa0ay3KEn8HyDZ0gIJljDts6pGE9RTgYA8wdp0X4l9D3eswdq/6yXh3jA1CV44I0rg6gh8KqZBQrr1FllzFo7ET19E/Ih7+1GDIjMgeYc7ZX6+KiUX7WP19HA==" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18:22-06:00" level=debug msg="completed challenge" Dec 30 11:18:22 volumio go-librespot[19346]: time="2025-12-30T11:18: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 " Dec 30 11:18:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:22 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:22 volumio sudo[19387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:22 volumio sudo[19387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:23 volumio sudo[19387]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:23 volumio volumio[18783]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 11:18:23 volumio sudo[19391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 11:18:23 volumio sudo[19391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:23 volumio sudo[19391]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:23 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 11:18:23 volumio volumio[18783]: info: Initializing connection to go-librespot Websocket Dec 30 11:18:23 volumio sudo[19394]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 11:18:23 volumio sudo[19394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:23 volumio volumio[18783]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 11:18:23 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 11:18:23 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 11:18:23 volumio sudo[19394]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:23 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:23 volumio sudo[19401]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:23 volumio sudo[19401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:24 volumio sudo[19401]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:24 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:24 volumio sudo[19404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:24 volumio sudo[19404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:24 volumio sudo[19404]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:25 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:25 volumio sudo[19407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:25 volumio sudo[19407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:25 volumio sudo[19407]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:25 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Dec 30 11:18:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:25 volumio sudo[19411]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:25 volumio sudo[19411]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:26 volumio go-librespot[19412]: go-librespot daemon starting... Dec 30 11:18:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="app state loaded" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:26 volumio sudo[19411]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:26 volumio volumio[18783]: info: Initializing connection to go-librespot Websocket Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="new websocket client" Dec 30 11:18:26 volumio volumio[18783]: info: Connection to go-librespot Websocket established Dec 30 11:18:26 volumio mpd[19340]: 2025-12-30T11:18:26 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-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]" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-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]" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=info msg="zeroconf server listening on port 36051" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="obtained new client token: AACGsNg+uWRxjeoIex/y+J5aCOV6mW9mB36bwYV/tgnD9TscpOsXL05LfFrOANcdjVscWXZz7ANqFKKjBWjII/Ah2rLKUq07jnUM45MpAytV40rtstIjD3W91//Iqi9qPEB1UO03mj91IHB/CseFFGl9uC+J7kheRRSnMtnlU8m9RaTGXz/8xhpVdEz6a5iVFWlC7skWr5z1MmSMBw5dCmm50CeS8x1cVDgi0ib1bH0/sTFmhQAsszEw6w==" Dec 30 11:18:26 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 11:18:26 volumio sudo[19262]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:26 volumio sudo[19125]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:26 volumio sudo[19135]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:26 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.8.63 Dec 30 11:18:26 volumio avahi-daemon[664]: Registering new address record for 169.254.8.63 on eth0.IPv4. Dec 30 11:18:26 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18:26-06:00" level=debug msg="completed challenge" Dec 30 11:18:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.8.63 Dec 30 11:18:26 volumio go-librespot[19414]: time="2025-12-30T11:18: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 " Dec 30 11:18:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 11:18:26 volumio volumio[18783]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:18:26 volumio volumio[18783]: assert.ok(self.idling) Dec 30 11:18:26 volumio volumio[18783]: error: The expression evaluated to a falsy value: Dec 30 11:18:26 volumio volumio[18783]: assert.ok(self.idling) Dec 30 11:18:26 volumio volumio[18783]: error: MPD error: The expression evaluated to a falsy value: Dec 30 11:18:26 volumio volumio[18783]: assert.ok(self.idling) Dec 30 11:18:26 volumio volumio[18783]: error: The expression evaluated to a falsy value: Dec 30 11:18:26 volumio volumio[18783]: assert.ok(self.idling) Dec 30 11:18:26 volumio volumio[18783]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 11:18:26 volumio volumio[18783]: info: Connection to go-librespot Websocket closed Dec 30 11:18:26 volumio volumio[18783]: info: MPD running with PID19340 Dec 30 11:18:26 volumio volumio[18783]: ,establishing connection Dec 30 11:18:26 volumio sudo[19442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 11:18:26 volumio sudo[19442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:26 volumio volumio[18783]: error: updateQueue error: null Dec 30 11:18:26 volumio volumio[18783]: error: updateQueue error: null Dec 30 11:18:26 volumio sudo[19442]: pam_unix(sudo:session): session closed for user root Dec 30 11:18:26 volumio volumio[18783]: info: Completed starting Core Plugins Dec 30 11:18:26 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:18:26 volumio volumio[18783]: info: ----- MyVolumio plugins startup ---- Dec 30 11:18:26 volumio volumio[18783]: info: ------------------------------------------- Dec 30 11:18:26 volumio volumio[18783]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 11:18:27 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.8.63 Dec 30 11:18:27 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.8.63 Dec 30 11:18:27 volumio avahi-daemon[664]: Withdrawing address record for 169.254.8.63 on eth0. Dec 30 11:18:27 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 11:18:27 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 11:18:27 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:27 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 11:18:27 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 11:18:28 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 11:18:29 volumio volumio[18783]: info: Getting Spotify volume Dec 30 11:18:29 volumio volumio[18783]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:18:29 volumio volumio[18783]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 11:18:29 volumio volumio[18783]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 11:18:29 volumio volumio[18783]: errno: -111, Dec 30 11:18:29 volumio volumio[18783]: code: 'ECONNREFUSED', Dec 30 11:18:29 volumio volumio[18783]: syscall: 'connect', Dec 30 11:18:29 volumio volumio[18783]: address: '127.0.0.1', Dec 30 11:18:29 volumio volumio[18783]: port: 9879, Dec 30 11:18:29 volumio volumio[18783]: response: undefined Dec 30 11:18:29 volumio volumio[18783]: } Dec 30 11:18:29 volumio volumio[18783]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 11:18:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Dec 30 11:18:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 11:18:29 volumio go-librespot[19487]: go-librespot daemon starting... Dec 30 11:18:29 volumio go-librespot[19488]: time="2025-12-30T11:18:29-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 11:18:29 volumio go-librespot[19488]: time="2025-12-30T11:18:29-06:00" level=debug msg="app state loaded" Dec 30 11:18:29 volumio go-librespot[19488]: time="2025-12-30T11:18:29-06:00" level=debug msg="stored credentials not found" Dec 30 11:18:29 volumio go-librespot[19488]: time="2025-12-30T11:18:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-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]" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-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]" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-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]" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-06:00" level=info msg="zeroconf server listening on port 34427" Dec 30 11:18:30 volumio sudo[19498]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 11:17' Dec 30 11:18:30 volumio sudo[19498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-06:00" level=debug msg="obtained new client token: AAAMe6lP9e9hsE55fATTUXrXxSegEdt6ERqrDSKVxszmmRunQpCLDo2FE5vosidsDo1q7v72OKI64TktY9xErFab8SOj8TeX2tU8qDivBWz3HzvWDlXN/LdequgxeR9pKZ2kHGERRk/CUdS6GcOgqo/Vzv8U45/Dn2jKAgSvQXolBjw0XGjAixklCZ7WQ0bwANxpfV9ASvuVA+LPnNTw2gMKWQsiLYPaOLZL1Ggbbrr7/Gx56UyWpfg=" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-06:00" level=debug msg="completed keyexchange" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18:30-06:00" level=debug msg="completed challenge" Dec 30 11:18:30 volumio go-librespot[19488]: time="2025-12-30T11:18: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 " Dec 30 11:18:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 11:18:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. 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"