Dec 30 06:19:00 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.17.234 Dec 30 06:19:00 volumio avahi-daemon[664]: Registering new address record for 169.254.17.234 on eth0.IPv4. Dec 30 06:19:00 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Dec 30 06:19:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:00 volumio go-librespot[17843]: go-librespot daemon starting... Dec 30 06:19:00 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:00 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:00 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.234 Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=debug msg="app state loaded" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:00 volumio go-librespot[17844]: time="2025-12-30T06:19:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:01 volumio volumio[17558]: info: Applying required configuration parameters for plugin volusonic Dec 30 06:19:01 volumio volumio[17558]: info: Loading plugin "backup_restore"... Dec 30 06:19:01 volumio volumio[17797]: Starting albumart workers Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-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 06:19:01 volumio volumio[17799]: Starting albumart workers Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=info msg="zeroconf server listening on port 36555" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="obtained new client token: AAD5oJBqmJ4tLWAwjiyaDUGeGPi8MXDQ2f0BeycBtZBzEu5l6y8bxFw7W84G6lW20fCb97zXb7EKgmzboDVOB7UqUkk199mND6Ljrl4NkIf+r/y/8XcLDGSd2f5mNegPz4TQk2rLt0sDYjXViQj++khOFrOs1fRgrl6LPfYA2shiRDTenoBOGP5rY8u42f8JEYHtgQg8bYFeRrbESCMLlvwZW6dbOV80pivfGWNjJ3x3K6735U/n/zlfgg==" Dec 30 06:19:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.17.234 Dec 30 06:19:01 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.17.234 Dec 30 06:19:01 volumio avahi-daemon[664]: Withdrawing address record for 169.254.17.234 on eth0. Dec 30 06:19:01 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:01 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=debug msg="completed challenge" Dec 30 06:19:01 volumio volumio[17558]: info: Applying required configuration parameters for plugin backup_restore Dec 30 06:19:01 volumio go-librespot[17844]: time="2025-12-30T06:19:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 06:19:01 volumio volumio[17798]: Starting albumart workers Dec 30 06:19:01 volumio volumio[17558]: info: Plugin rpi_eeprom_config is not enabled Dec 30 06:19:01 volumio volumio[17558]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 06:19:01 volumio volumio[17558]: info: Loading plugin "scheduledrestart"... Dec 30 06:19:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:02 volumio volumio[17558]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 06:19:02 volumio volumio[17558]: info: Plugin Bluetoothremote is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Plugin music_services_shield is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Loading plugin "Systeminfo"... Dec 30 06:19:02 volumio volumio[17558]: info: Plugin peppymeterbasic is not enabled Dec 30 06:19:02 volumio volumio[17558]: info: Loading plugin "peppyspectrum"... Dec 30 06:19:02 volumio volumio[17558]: info: Loading i18n strings for locale en Dec 30 06:19:02 volumio volumio[17558]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:02 volumio volumio[17558]: Updating browse sources language Dec 30 06:19:02 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::initPlayerControls Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: Express server listening on port 3000 Dec 30 06:19:03 volumio volumio[17558]: [Metrics] WebUI: 20s 604.36ms Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::resetVolumioState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::getcurrentVolume Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:03 volumio sudo[17891]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:19:03 volumio sudo[17891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17891]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio sudo[17893]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:19:03 volumio sudo[17893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17893]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: Volumio Network Manager: Network status updated: 1 Dec 30 06:19:03 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::updateTrackBlock Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrackBlock Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:03 volumio volumio[17558]: info: Reloading queue from file Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::setRepeat null single undefined Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::setRandom null Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: Setting Device type: Raspberry PI Dec 30 06:19:03 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:03 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:03 volumio volumio[17558]: info: Completed loading Core Plugins Dec 30 06:19:03 volumio volumio[17558]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:03 volumio sudo[17907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 06:19:03 volumio sudo[17907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: Found device Volumio Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:03 volumio volumio[17558]: info: Discovery: Found device Volumio Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:03 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:03 volumio volumio[17558]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:03 volumio volumio[17558]: info: Reading ALSA contributions from plugins. Dec 30 06:19:03 volumio volumio[17558]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:03 volumio volumio[17558]: info: Output device has changed, restarting MPD Dec 30 06:19:03 volumio sudo[17907]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:03 volumio sudo[17910]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:03 volumio sudo[17910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17910]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio sudo[17912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:03 volumio sudo[17912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:03 volumio volumio[17558]: info: ___________ START PLUGINS ___________ Dec 30 06:19:03 volumio volumio[17558]: info: ControllerMpd::onStart: Initializing MPD Dec 30 06:19:03 volumio volumio[17558]: info: Creating MPD Configuration file Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:03 volumio volumio[17558]: info: [1767097143901] CoreMusicLibrary::Adding element Media Servers Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:03 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 06:19:03 volumio sudo[17922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:03 volumio sudo[17920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:03 volumio sudo[17922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:03 volumio sudo[17920]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:03 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:04 volumio systemd[1]: mpd.service: Consumed 6.153s CPU time. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144079] CoreMusicLibrary::Adding element Last_100 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144089] CoreMusicLibrary::Adding element Webradio Dec 30 06:19:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:04 volumio volumio[17558]: info: Initializing BBC Radios Dec 30 06:19:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144229] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144248] CoreMusicLibrary::Adding element SoundCloud Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: info: Creating Spotify config file Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:04 volumio sudo[17947]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:04 volumio sudo[17947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:04 volumio sudo[17947]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:04 volumio volumio[17558]: info: [squeezelite_mc] Starting proxy server... Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144928] CoreMusicLibrary::Adding element YouTube2 Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Dec 30 06:19:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144962] CoreMusicLibrary::Adding element YouTube Music Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:04 volumio volumio[17558]: info: [1767097144984] CoreMusicLibrary::Adding element Podcast Dec 30 06:19:04 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:04 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:05 volumio go-librespot[17952]: go-librespot daemon starting... Dec 30 06:19:05 volumio volumio[17558]: info: Loading i18n strings for locale en Dec 30 06:19:05 volumio volumio[17558]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:05 volumio volumio[17558]: Updating browse sources language Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:05 volumio volumio[17558]: info: [1767097145078] CoreMusicLibrary::Adding element Volusonic Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:05 volumio volumio[17558]: Cannot find translation for source Volusonic Dec 30 06:19:05 volumio go-librespot[17953]: time="2025-12-30T06:19:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:05 volumio volumio[17558]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 06:19:05 volumio volumio[17558]: info: Volumio Calling Home Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Proxy server started on port 34299 Dec 30 06:19:05 volumio volumio[17558]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:05 volumio volumio[17558]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:05 volumio volumio[17558]: info: Reading ALSA contributions from plugins. Dec 30 06:19:05 volumio go-librespot[17953]: time="2025-12-30T06:19:05-06:00" level=info msg="zeroconf server listening on port 46211" Dec 30 06:19:05 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:05 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:05 volumio volumio[17558]: info: Upmpdcli Daemon Started Dec 30 06:19:05 volumio volumio[17558]: info: Volumio called home Dec 30 06:19:05 volumio volumio[17558]: info: Spotify config file written Dec 30 06:19:05 volumio sudo[17980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 06:19:05 volumio sudo[17980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:05 volumio volumio[17558]: 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 06:19:05 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 30 06:19:05 volumio volumio[17558]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:05 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 30 06:19:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:05 volumio volumio[17558]: info: CoreStateMachine::pushState Dec 30 06:19:05 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Server discovery started Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Player finder started Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:05 volumio go-librespot[17982]: go-librespot daemon starting... Dec 30 06:19:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:06 volumio sudo[17980]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="app state loaded" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: No need to fix Spotify hosts Dec 30 06:19:06 volumio volumio[17558]: 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 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-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 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=info msg="zeroconf server listening on port 42681" Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 06:19:06 volumio volumio[17558]: 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 06:19:06 volumio volumio[17558]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:06 volumio volumio[17558]: SPOTIFY: BQBiNCS9WwXkYptb9ZJe6puZ0h7I74ZPQIz4usJLBe0WIQf_gXYhoqQIurhx1UxWQFgQfhZ4UWbBB3ecbUoZuGNkRxM9-ipAKStEIMRLC4ytackQYWz8dHDjjfbG48qtvU7uaJXnLCqksv0jZ5tYvnoqqjNLxBxCEd8_zhtlsbDTQYRreXjBHpZxweORoTm4v6YrKZBl-KFyrWa8mi9_Eee2jo1PmqhkR3SkiXQ Dec 30 06:19:06 volumio volumio[17558]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:06 volumio volumio[17558]: info: New Spotify access token = BQBiNCS9WwXkYptb9ZJe6puZ0h7I74ZPQIz4usJLBe0WIQf_gXYhoqQIurhx1UxWQFgQfhZ4UWbBB3ecbUoZuGNkRxM9-ipAKStEIMRLC4ytackQYWz8dHDjjfbG48qtvU7uaJXnLCqksv0jZ5tYvnoqqjNLxBxCEd8_zhtlsbDTQYRreXjBHpZxweORoTm4v6YrKZBl-KFyrWa8mi9_Eee2jo1PmqhkR3SkiXQ Dec 30 06:19:06 volumio volumio[17558]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 06:19:06 volumio sudo[18005]: 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 06:19:06 volumio sudo[18005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18005]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="obtained new client token: AACW5XYRyfMpVhEANoT3MQG8Q79twFCgPw6yTul3jCzYFauWk0va8mBQWOyuAFm3nOABBCUEeeGbqmZStaKwRq4xix2V0eWX3PaNg6Dz8KrTLbVAXO0DsyRsTm4rCe20ms9dHmEcbD3G+m64hy1ABsXdqz+GFlvm9xb/3k387l58EeDpmVfYlh/qffFbu67XkXaHoW1QP+BBexgLle+9W/ajpHHwCuOvd1RCcVdvkSusW88vPy1QvL65GQ==" Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:06 volumio sudo[18009]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18011]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18011]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:06 volumio sudo[18014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:06 volumio sudo[18014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.128.54 Dec 30 06:19:06 volumio avahi-daemon[664]: Registering new address record for 169.254.128.54 on eth0.IPv4. Dec 30 06:19:06 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19:06-06:00" level=debug msg="completed challenge" Dec 30 06:19:06 volumio go-librespot[17985]: time="2025-12-30T06:19: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 06:19:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:06 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:06 volumio volumio[17558]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 06:19:06 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:06 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:06 volumio systemd[1]: shairport-sync.service: Consumed 2.096s CPU time. Dec 30 06:19:06 volumio sudo[18036]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 06:19:06 volumio sudo[18036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:06 volumio sudo[18036]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio volumio[17558]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:06 volumio volumio[17558]: info: Output device has changed, restarting MPD Dec 30 06:19:06 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:06 volumio volumio[17558]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:06 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:06 volumio sudo[18011]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:06 volumio sudo[18014]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio sudo[18009]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio sudo[18040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:07 volumio sudo[18040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:07 volumio sudo[18042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18040]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio volumio[17558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.128.54 Dec 30 06:19:07 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:07 volumio systemd[1]: mpd.service: Consumed 2.694s CPU time. Dec 30 06:19:07 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:07 volumio mpd_monitor.sh[17951]: MPD error: Connection reset by peer Dec 30 06:19:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:07 volumio mpd_monitor.sh[15947]: MPD Monitor Service: MPD Appears to be inactive, restarting Dec 30 06:19:07 volumio mpd_monitor.sh[18065]: mpd: no process found Dec 30 06:19:07 volumio volumio[17558]: 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 06:19:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:07 volumio sudo[18071]: 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 06:19:07 volumio sudo[18071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio sudo[18071]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:07 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:07 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:07 volumio volumio[17558]: info: MPD Permissions set Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: Error adding Membership: Error: addMembership EINVAL Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:07 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:07 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:07 volumio sudo[18076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 06:19:07 volumio sudo[18076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:07 volumio systemd[1]: Reloading. Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.128.54 Dec 30 06:19:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.128.54 Dec 30 06:19:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.128.54 on eth0. Dec 30 06:19:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:07 volumio volumio[17558]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:07 volumio volumio[17558]: info: Starting Shairport Sync Dec 30 06:19:07 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:07 volumio volumio[17558]: 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 06:19:07 volumio volumio[17558]: info: Spotify Successfully logged in Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:07 volumio volumio[17558]: info: [1767097147904] CoreMusicLibrary::Adding element Spotify Dec 30 06:19:07 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source SoundCloud Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source YouTube2 Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source YouTube Music Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Podcast Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Volusonic Dec 30 06:19:07 volumio volumio[17558]: Cannot find translation for source Spotify Dec 30 06:19:07 volumio sudo[18102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:07 volumio sudo[18102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:08 volumio sudo[18079]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:08 volumio sudo[18079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:08 volumio sudo[18079]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:08 volumio volumio[17558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:09 volumio volumio[17558]: info: go-librespot daemon successfully initialized Dec 30 06:19:10 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 06:19:10 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 06:19:10 volumio sudo[18076]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:10 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:10 volumio sudo[18124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:10 volumio sudo[18124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 30 06:19:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:11 volumio sudo[18124]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:11 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 06:19:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:11 volumio sudo[18128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 06:19:11 volumio sudo[18128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:11 volumio go-librespot[18127]: go-librespot daemon starting... Dec 30 06:19:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:11 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:11 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:11 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:11 volumio systemd[1]: shairport-sync.service: Consumed 1.361s CPU time. Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="app state loaded" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:11 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:11 volumio sudo[18102]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio volumio[17558]: info: Shairport-Sync Started Dec 30 06:19:11 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:11 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 06:19:11 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-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 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-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 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-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 06:19:11 volumio sudo[18128]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=info msg="zeroconf server listening on port 33311" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="obtained new client token: AADsx4+pYkWGNz0TWzgLJQ3wzwjvS8yV5WHq+dWrijwmzUW7xoudSuz3HMXmtInYKiMxrVEDnuqOyxHTBWpV6lYWEcRl0EGLRuzH2fY11kugdP5zcPFz76yZv5epk8yNTgoWXJaaxTT/dScx5zE97OYb8+y+iUBR55OTgeAMy8vnQKNAxHC+WdBkTEReA3fNHuZw6o3aIrWY1j5KaJZz8Em/CnGejIADmCDFK1o3FR1AFiHvplC4obXtcg==" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-06:00" level=debug msg="completed challenge" Dec 30 06:19:11 volumio go-librespot[18130]: time="2025-12-30T06:19:11-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 06:19:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:11 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:11 volumio sudo[18153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:11 volumio sudo[18153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18153]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 06:19:12 volumio sudo[18157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 06:19:12 volumio sudo[18157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18157]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 06:19:12 volumio sudo[18160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 06:19:12 volumio sudo[18160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:12 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:12 volumio sudo[18160]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:12 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:12 volumio volumio[17558]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.75.189 Dec 30 06:19:12 volumio avahi-daemon[664]: Registering new address record for 169.254.75.189 on eth0.IPv4. Dec 30 06:19:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:12 volumio volumio-remote-updater[702]: [2025-12-30 06:19:12] [connect] Successful connection Dec 30 06:19:12 volumio volumio-remote-updater[702]: [2025-12-30 06:19:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767097152 101 Dec 30 06:19:12 volumio volumio[17558]: 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 06:19:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:12 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:12 volumio sudo[18183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:12 volumio sudo[18183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:12 volumio sudo[18183]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:13 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:13 volumio sudo[18186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:13 volumio sudo[18186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.189 Dec 30 06:19:13 volumio sudo[18186]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:13 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:19:14 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:14 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.75.189 Dec 30 06:19:14 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.75.189 Dec 30 06:19:14 volumio avahi-daemon[664]: Withdrawing address record for 169.254.75.189 on eth0. Dec 30 06:19:14 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:14 volumio mpd[18122]: 2025-12-30T06:19:14 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 06:19:14 volumio sudo[18190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:14 volumio sudo[18190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:14 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:14 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:14 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:14 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:14 volumio sudo[18190]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 06:19:14 volumio sudo[18042]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio mpd_monitor.sh[15947]: MPD Monitor Service: MPD restarted due to no mpc output. Dec 30 06:19:14 volumio sudo[17922]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio sudo[17912]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio volumio[17558]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: error: The expression evaluated to a falsy value: Dec 30 06:19:14 volumio volumio[17558]: assert.ok(self.idling) Dec 30 06:19:14 volumio volumio[17558]: info: MPD running with PID18122 Dec 30 06:19:14 volumio volumio[17558]: ,establishing connection Dec 30 06:19:14 volumio volumio[17558]: error: updateQueue error: null Dec 30 06:19:14 volumio volumio[17558]: error: updateQueue error: null Dec 30 06:19:14 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:14 volumio sudo[18214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:14 volumio sudo[18214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 06:19:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:14 volumio sudo[18214]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:14 volumio go-librespot[18216]: go-librespot daemon starting... Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=debug msg="app state loaded" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:14 volumio go-librespot[18217]: time="2025-12-30T06:19:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19: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 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19: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 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19: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 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=info msg="zeroconf server listening on port 39543" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="obtained new client token: AABtQhpy8+C+Qc/RKG8NfRDwTwX5Ho8ypp7iQGe69+Xw4ztxx73C6X2nhGNYsUAhtQoSW4r9uBosKR4VpXIHyKQKoN/7Q7Bt253NGtYEhXOUL6TYM4UXKHBz9HKi2BZfziZaECPk4BdbL3sCT+JCfAIJ7M/N7tQlnVx57qe48PMs3MK/REZdzBkrjBJIP37tyezp6Vk2iqirx/Bj/VqSHG3dYYOMxLWfppaRyERDXaA1FPmWOXmIhyQ=" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:15 volumio volumio[17558]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-06:00" level=debug msg="completed challenge" Dec 30 06:19:15 volumio sudo[18225]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:15 volumio sudo[18225]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:15 volumio go-librespot[18217]: time="2025-12-30T06:19:15-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 06:19:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:15 volumio sudo[18225]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:15 volumio volumio[17558]: info: Completed starting Core Plugins Dec 30 06:19:15 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:19:15 volumio volumio[17558]: info: ----- MyVolumio plugins startup ---- Dec 30 06:19:15 volumio volumio[17558]: info: ------------------------------------------- Dec 30 06:19:15 volumio volumio[17558]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 06:19:15 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:15 volumio volumio[17558]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:17 volumio sudo[18242]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio sudo[18244]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio sudo[18246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:19:17 volumio sudo[18246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:17 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 06:19:17 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 06:19:17 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 06:19:17 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 06:19:17 volumio sudo[18244]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio sudo[18246]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio mpd_monitor.sh[18250]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 06:19:17 volumio sudo[18242]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:17 volumio volumio[17558]: info: Successfully started MPD Monitor Dec 30 06:19:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 06:19:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:18 volumio go-librespot[18254]: go-librespot daemon starting... Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="app state loaded" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:18 volumio volumio[17558]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="new websocket client" Dec 30 06:19:18 volumio volumio[17558]: info: Connection to go-librespot Websocket established Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-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 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-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 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-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 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=info msg="zeroconf server listening on port 40283" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="obtained new client token: AACAOw2KOTHfGgSh4gf2zbfFDf7PQhci9EYnB6AIWva7Gi1mlmHrDhj0ZzM7ZxBHItohbrt3g1fRgC9ICX1wSuu6uCy3K08NDX00VnTBnBmGSX73O04P14N/ggWpFb0Zc84x8cLrwYo6yUb1wNiocvsLVCmwGiUI4b7SQ4ubVZmGYnUergVpV/5z7T3/sUrqKko0La2Q3XL6sQJJc+Ydgvb261hvPJwqvzR6+6UpSQyfFb1Wp9I65g55Tg==" Dec 30 06:19:18 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.53.93 Dec 30 06:19:18 volumio avahi-daemon[664]: Registering new address record for 169.254.53.93 on eth0.IPv4. Dec 30 06:19:18 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:18 volumio go-librespot[18255]: time="2025-12-30T06:19:18-06:00" level=debug msg="completed challenge" Dec 30 06:19:19 volumio go-librespot[18255]: time="2025-12-30T06:19: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 06:19:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:19 volumio volumio[17558]: info: Connection to go-librespot Websocket closed Dec 30 06:19:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.53.93 Dec 30 06:19:19 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:19:20 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.53.93 Dec 30 06:19:20 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.53.93 Dec 30 06:19:20 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:20 volumio avahi-daemon[664]: Withdrawing address record for 169.254.53.93 on eth0. Dec 30 06:19:20 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:20 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:20 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:20 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:21 volumio volumio[17558]: info: Getting Spotify volume Dec 30 06:19:21 volumio volumio[17558]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:19:21 volumio volumio[17558]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:21 volumio volumio[17558]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 06:19:21 volumio volumio[17558]: errno: -111, Dec 30 06:19:21 volumio volumio[17558]: code: 'ECONNREFUSED', Dec 30 06:19:21 volumio volumio[17558]: syscall: 'connect', Dec 30 06:19:21 volumio volumio[17558]: address: '127.0.0.1', Dec 30 06:19:21 volumio volumio[17558]: port: 9879, Dec 30 06:19:21 volumio volumio[17558]: response: undefined Dec 30 06:19:21 volumio volumio[17558]: } Dec 30 06:19:21 volumio volumio[17558]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:19:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 30 06:19:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:22 volumio go-librespot[18308]: go-librespot daemon starting... Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="app state loaded" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-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 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-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 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=info msg="zeroconf server listening on port 36477" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="obtained new client token: AACpasZSFBlCnHq9qpxQ5Zm/5HqWDBybGTHy0m+Tp5+AgK4o6WvknsEm6z0HMDdTNj+mAVZZ7uDDV2K5ZvKLVKTp/N6VW03LZOvJF9+2++HCmccdvYEn6Cu9Aew9vRpDyo4SkRERokyearfKJt0ic7OlrcvJC4Y/JBPO8wIGTHr3MNFZeZpmrvLlg8WY/TP8f+AZA/BhMuK7LKVUjEzeSD7Bs7Kx64J/Fp3+8EsqT7iQWgYDMXaR+Ssd5w==" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:22 volumio go-librespot[18309]: time="2025-12-30T06:19:22-06:00" level=debug msg="completed challenge" Dec 30 06:19:23 volumio go-librespot[18309]: time="2025-12-30T06:19: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 06:19:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:23 volumio sudo[18318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:18' Dec 30 06:19:23 volumio sudo[18318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:23 volumio sudo[18318]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:24 volumio volumio-remote-updater[702]: [2025-12-30 06:19:24] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 06:19:24 volumio volumio-remote-updater[702]: [2025-12-30 06:19:24] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 06:19:24 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:24 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 06:19:24 volumio systemd[1]: volumio.service: Consumed 53.804s CPU time. Dec 30 06:19:24 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:19:24 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:19:24 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 396. Dec 30 06:19:24 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:19:24 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 06:19:24 volumio systemd[1]: volumio.service: Consumed 53.804s CPU time. Dec 30 06:19:24 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 06:19:24 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:19:25 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.101.57 Dec 30 06:19:25 volumio avahi-daemon[664]: Registering new address record for 169.254.101.57 on eth0.IPv4. Dec 30 06:19:25 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.101.57 Dec 30 06:19:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 30 06:19:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:26 volumio go-librespot[18364]: go-librespot daemon starting... Dec 30 06:19:26 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="app state loaded" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:26 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:26 volumio volumio[18333]: info: ----- Volumio3 ---- Dec 30 06:19:26 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:26 volumio volumio[18333]: info: ----- System startup ---- Dec 30 06:19:26 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-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 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-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 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=info msg="zeroconf server listening on port 35791" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="obtained new client token: AAC/aujOpXUeEr+swK36hFxQVpUVul25mvGh/tgkWKSjD4V7avsUYnYQXod8rI4ByUH3dHFGUpslOMS2ypxwAAicyL8BhLrup36/n5Hsh/D72+WB5/ng6Ayafh8XwZCdCur3L5B/WAjvbI4keK0xAY0yaMMElbxPxyH/rnIyGlmo51FifqI7WX6B0o7e4sHCXY1Zet5oQdmx1NX4yix/2SyvTHlfg14he/PmegDibGxEKP2acRZQ0qAuJw==" Dec 30 06:19:26 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.101.57 Dec 30 06:19:26 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.101.57 Dec 30 06:19:26 volumio avahi-daemon[664]: Withdrawing address record for 169.254.101.57 on eth0. Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:26 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:26 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:26 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19:26-06:00" level=debug msg="completed challenge" Dec 30 06:19:26 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:26 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:26 volumio go-librespot[18365]: time="2025-12-30T06:19: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 06:19:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:27 volumio volumio[18333]: info: MYVOLUMIO Environment detected Dec 30 06:19:27 volumio volumio[18333]: info: Plugin folders cleanup Dec 30 06:19:27 volumio volumio[18333]: info: Scanning into folder /volumio/app/plugins/ Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category audio_interface Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category miscellanea Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category music_service Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category plugins.json Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category system_controller Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category user_interface Dec 30 06:19:27 volumio volumio[18333]: info: Scanning into folder /data/plugins/ Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category audio_interface Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category music_service Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category system_controller Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category system_hardware Dec 30 06:19:27 volumio volumio[18333]: info: Scanning category user_interface Dec 30 06:19:27 volumio volumio[18333]: info: Plugin folders cleanup completed Dec 30 06:19:27 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:27 volumio volumio[18333]: info: ----- Core plugins startup ---- Dec 30 06:19:27 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:27 volumio volumio[18333]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 06:19:27 volumio volumio[18333]: info: Adding plugin upnp to MyMusic Plugins Dec 30 06:19:27 volumio volumio[18333]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 06:19:27 volumio volumio[18333]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 06:19:27 volumio volumio[18333]: info: Loading plugins from folder /data/plugins/ Dec 30 06:19:27 volumio volumio[18333]: info: Loading plugin "system"... Dec 30 06:19:27 volumio volumio[18333]: info: Loading plugin "appearance"... Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "network"... Dec 30 06:19:28 volumio volumio[18333]: info: Refreshing Cached IP Addresses Dec 30 06:19:28 volumio sudo[18402]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:19:28 volumio sudo[18402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:28 volumio sudo[18402]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:28 volumio sudo[18404]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:19:28 volumio sudo[18404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "services"... Dec 30 06:19:28 volumio sudo[18404]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "alsa_controller"... Dec 30 06:19:28 volumio sudo[18412]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 06:19:28 volumio sudo[18412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:28 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "wizard"... Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "networkfs"... Dec 30 06:19:28 volumio volumio[18333]: info: Starting Udev Watcher for removable devices Dec 30 06:19:28 volumio volumio[18333]: info: Ignoring mount for partition: boot Dec 30 06:19:28 volumio volumio[18333]: info: Ignoring mount for partition: volumio Dec 30 06:19:28 volumio volumio[18333]: info: Ignoring mount for partition: volumio_data Dec 30 06:19:28 volumio volumio[18333]: info: Mounting Device Wikipedia Dec 30 06:19:28 volumio sudo[18441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 06:19:28 volumio sudo[18441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:28 volumio sudo[18441]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:28 volumio volumio[18333]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:19:28 volumio volumio[18333]: dmesg(1) may have more information after failed mount system call. Dec 30 06:19:28 volumio volumio[18333]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 06:19:28 volumio volumio[18333]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:19:28 volumio volumio[18333]: dmesg(1) may have more information after failed mount system call. Dec 30 06:19:28 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "volumio_command_line_client"... Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "upnp"... Dec 30 06:19:28 volumio volumio[18333]: info: [1767097168938] Starting Upmpd Daemon Dec 30 06:19:28 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "my_music"... Dec 30 06:19:28 volumio volumio[18333]: info: Loading plugin "mpd"... Dec 30 06:19:29 volumio sudo[18412]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:29 volumio volumio-remote-updater[702]: [2025-12-30 06:19:29] [connect] Successful connection Dec 30 06:19:29 volumio volumio[18333]: info: Loading plugin "upnp_browser"... Dec 30 06:19:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 30 06:19:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:30 volumio go-librespot[18443]: go-librespot daemon starting... Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="app state loaded" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:30 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19: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-gew1.spotify.com:80]" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-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 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-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 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=info msg="zeroconf server listening on port 32827" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="obtained new client token: AABNeuJeP8H+AOaMNfRK22R8C5foua9cKmrppCFEwPbMFX6fyiQwvdCODjJQxIfDDv+diIN/JYbbErKBHFe/OmXu1FIuXu8BTxzQcvTnbDu7VTy0sUGmgilv7sPdj1mYzXODquWAi6fZq4Y+uFPDBaFENb0dwdm9Vg5V/YdFxeREd5G+f5RbqFJ+IMeJu+1uPBPEslc8ZS80kxxeAsUFZ6dUReBW4P2odkPVmgUUM0/Ca6wWUF9I2mKuMw==" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19:30-06:00" level=debug msg="completed challenge" Dec 30 06:19:30 volumio go-librespot[18444]: time="2025-12-30T06:19: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 06:19:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:31 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.84.205 Dec 30 06:19:31 volumio avahi-daemon[664]: Registering new address record for 169.254.84.205 on eth0.IPv4. Dec 30 06:19:31 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.84.205 Dec 30 06:19:32 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.84.205 Dec 30 06:19:32 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.84.205 Dec 30 06:19:32 volumio avahi-daemon[664]: Withdrawing address record for 169.254.84.205 on eth0. Dec 30 06:19:32 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:32 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "alarm-clock"... Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "airplay_emulation"... Dec 30 06:19:32 volumio volumio[18333]: info: Starting Shairport Sync Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "last_100"... Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "webradio"... Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "i2s_dacs"... Dec 30 06:19:32 volumio volumio[18333]: info: I2S DAC not set, start Auto-detection Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "volumiodiscovery"... Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** For more information see Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:19:32 volumio volumio[18333]: *** WARNING *** For more information see Dec 30 06:19:32 volumio node[18333]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:19:32 volumio node[18333]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:19:32 volumio node[18333]: *** WARNING *** For more information see Dec 30 06:19:32 volumio node[18333]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:19:32 volumio node[18333]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:19:32 volumio node[18333]: *** WARNING *** For more information see Dec 30 06:19:32 volumio volumio[18333]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 06:19:32 volumio volumio[18333]: info: Discovery: Started advertising with name: Volumio Dec 30 06:19:32 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:19:32 volumio volumio[18333]: info: Loading plugin "bandcamp"... Dec 30 06:19:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 30 06:19:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:34 volumio go-librespot[18486]: go-librespot daemon starting... Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="app state loaded" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-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 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-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 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=info msg="zeroconf server listening on port 37151" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="obtained new client token: AACBg94buiHgQ5NcmQrnIjfmNK9dc68rmFIqi8LqOzfOK/NtHgkhQFjgIhvSujPuoW2rN0fkZwPS8mOhn44Pxyvy9dj4G2zbCijN4v4HdViiaupKCqz7hqdqVSnIkWAMAaX3lzif2ZrHJhhT4lCd3DKYy5qMePmse63OTSKiUGzEzKs8ExLDvICE4yuYDvd8GshN1XSSCQXxla7nwKkT1TxXuO12ZeDo84zeSufVDlhBwPBxrXg1ZnT+8g==" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=debug msg="completed challenge" Dec 30 06:19:34 volumio go-librespot[18487]: time="2025-12-30T06:19:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 06:19:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:35 volumio volumio[18333]: info: Plugin calmradio is not enabled Dec 30 06:19:35 volumio volumio[18333]: info: Loading plugin "soundcloud"... Dec 30 06:19:35 volumio volumio[18333]: info: Loading plugin "spop"... Dec 30 06:19:36 volumio volumio[18333]: info: Loading plugin "squeezelite_mc"... Dec 30 06:19:37 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.72.239 Dec 30 06:19:37 volumio avahi-daemon[664]: Registering new address record for 169.254.72.239 on eth0.IPv4. Dec 30 06:19:37 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:37 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:37 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:37 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.239 Dec 30 06:19:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.239 Dec 30 06:19:37 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.72.239 Dec 30 06:19:37 volumio avahi-daemon[664]: Withdrawing address record for 169.254.72.239 on eth0. Dec 30 06:19:37 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:37 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:37 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:37 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:37 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:37 volumio volumio[18333]: info: Loading plugin "youtube2"... Dec 30 06:19:38 volumio volumio[18333]: info: Loading plugin "ytcr"... Dec 30 06:19:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 30 06:19:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:38 volumio go-librespot[18530]: go-librespot daemon starting... Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=debug msg="app state loaded" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-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 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-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 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-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 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=info msg="zeroconf server listening on port 36015" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=debug msg="obtained new client token: AABva3P4qsssusBxSTwodDkZag6M4wvzZWmy5I9GqHy3oW18WdYsj/8FCiAV/EQqDT8rjM4D8rIYYZJtOHg0VB4NnXkTqUGFmu4QFjv7qUo86QRLUak2cUY7cSAMLFDaXUAg9Zjia6XG7xJvvQmu1xrg2tIfgRSlnvVTkjNuuz9SUAGDKCkarqvkFyNfqMqFqVWKUyVCzoguLmTZJU5BJVkiNAiHIXuZjgj19GJAbxHG0HsCtGencwBoDA==" Dec 30 06:19:38 volumio go-librespot[18531]: time="2025-12-30T06:19:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:39 volumio go-librespot[18531]: time="2025-12-30T06:19:39-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:39 volumio go-librespot[18531]: time="2025-12-30T06:19:39-06:00" level=debug msg="completed challenge" Dec 30 06:19:39 volumio go-librespot[18531]: time="2025-12-30T06:19: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 06:19:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:40 volumio volumio[18333]: info: Loading plugin "ytmusic"... Dec 30 06:19:41 volumio volumio[18333]: info: Plugin now_playing is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "outputs"... Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "albumart"... Dec 30 06:19:41 volumio volumio[18333]: info: Plugin example_plugin is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "inputs"... Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "updater_comm"... Dec 30 06:19:41 volumio volumio[18333]: info: Plugin mpdemulation is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "rest_api"... Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "websocket"... Dec 30 06:19:41 volumio volumio[18333]: info: Starting Socket.io Server version 1.7.4 Dec 30 06:19:41 volumio volumio[18333]: info: Plugin fusiondsp is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Plugin mpdoutput is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Plugin RoonBridge is not enabled Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "podcast"... Dec 30 06:19:41 volumio volumio-remote-updater[702]: [2025-12-30 06:19:41] [connect] Successful connection Dec 30 06:19:41 volumio volumio[18333]: info: ControllerPodcast::constructor Dec 30 06:19:41 volumio volumio[18333]: info: Loading plugin "volusonic"... Dec 30 06:19:42 volumio volumio[18553]: Forking 3 albumart workers Dec 30 06:19:42 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.140.213 Dec 30 06:19:42 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:42 volumio avahi-daemon[664]: Registering new address record for 169.254.140.213 on eth0.IPv4. Dec 30 06:19:42 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:42 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:42 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:42 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.140.213 Dec 30 06:19:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 30 06:19:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:42 volumio go-librespot[18610]: go-librespot daemon starting... Dec 30 06:19:42 volumio go-librespot[18611]: time="2025-12-30T06:19:42-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:42 volumio go-librespot[18611]: time="2025-12-30T06:19:42-06:00" level=debug msg="app state loaded" Dec 30 06:19:42 volumio go-librespot[18611]: time="2025-12-30T06:19:42-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:42 volumio go-librespot[18611]: time="2025-12-30T06:19:42-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:42 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.140.213 Dec 30 06:19:42 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.140.213 Dec 30 06:19:42 volumio avahi-daemon[664]: Withdrawing address record for 169.254.140.213 on eth0. Dec 30 06:19:42 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:43 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:43 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:43 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-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 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-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 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-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 06:19:43 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-06:00" level=info msg="zeroconf server listening on port 45681" Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-06:00" level=debug msg="obtained new client token: AAAT37ygVopSVLO+bGpwgT0q5Wm1BfOg2294dfYb19wXyj9GSL1MBCf1a9KHiU5Say4WXH8AQiG7CT9fYEAhNyByMTYF5PLg3hsg4Y3hi/ppIaKyNbDYGIoM6D5p6mFpZF3xnfmxXFyouXQYzFY9xkv0SEqDEr2BDOgt5FqSnQIsVcHTuDOF5GL6Exo1PVdgT4Sq04gUrFVvX2aEsVHMNpMtNs0x/rCyzR1GRcnq5Fpce5uhQS0dmPmqyg==" Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-06:00" level=debug msg="completed challenge" Dec 30 06:19:43 volumio go-librespot[18611]: time="2025-12-30T06:19:43-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 06:19:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:44 volumio volumio[18333]: info: Applying required configuration parameters for plugin volusonic Dec 30 06:19:44 volumio volumio[18333]: info: Loading plugin "backup_restore"... Dec 30 06:19:44 volumio volumio[18564]: Starting albumart workers Dec 30 06:19:44 volumio volumio[18565]: Starting albumart workers Dec 30 06:19:44 volumio volumio[18566]: Starting albumart workers Dec 30 06:19:45 volumio volumio[18333]: info: Applying required configuration parameters for plugin backup_restore Dec 30 06:19:45 volumio volumio[18333]: info: Plugin rpi_eeprom_config is not enabled Dec 30 06:19:45 volumio volumio[18333]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 06:19:45 volumio volumio[18333]: info: Loading plugin "scheduledrestart"... Dec 30 06:19:45 volumio volumio[18333]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 06:19:45 volumio volumio[18333]: info: Plugin Bluetoothremote is not enabled Dec 30 06:19:45 volumio volumio[18333]: info: Plugin music_services_shield is not enabled Dec 30 06:19:45 volumio volumio[18333]: info: Loading plugin "Systeminfo"... Dec 30 06:19:46 volumio volumio[18333]: info: Plugin peppymeterbasic is not enabled Dec 30 06:19:46 volumio volumio[18333]: info: Loading plugin "peppyspectrum"... Dec 30 06:19:46 volumio volumio[18333]: info: Loading i18n strings for locale en Dec 30 06:19:46 volumio volumio[18333]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:46 volumio volumio[18333]: Updating browse sources language Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::initPlayerControls Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:46 volumio volumio[18333]: Express server listening on port 3000 Dec 30 06:19:46 volumio volumio[18333]: [Metrics] WebUI: 20s 655.36ms Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::resetVolumioState Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::getcurrentVolume Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:46 volumio sudo[18657]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:19:46 volumio sudo[18657]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:46 volumio sudo[18659]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:19:46 volumio sudo[18659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 30 06:19:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:46 volumio sudo[18659]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:46 volumio sudo[18657]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:46 volumio volumio[18333]: info: Volumio Network Manager: Network status updated: 1 Dec 30 06:19:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:46 volumio go-librespot[18663]: go-librespot daemon starting... Dec 30 06:19:46 volumio go-librespot[18665]: time="2025-12-30T06:19:46-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:46 volumio go-librespot[18665]: time="2025-12-30T06:19:46-06:00" level=debug msg="app state loaded" Dec 30 06:19:46 volumio go-librespot[18665]: time="2025-12-30T06:19:46-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:46 volumio go-librespot[18665]: time="2025-12-30T06:19:46-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:46 volumio volumio[18333]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::pushState Dec 30 06:19:46 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::updateTrackBlock Dec 30 06:19:46 volumio volumio[18333]: info: CorePlayQueue::getTrackBlock Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:46 volumio volumio[18333]: info: Reloading queue from file Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::setRepeat null single undefined Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::pushState Dec 30 06:19:46 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::setRandom null Dec 30 06:19:46 volumio volumio[18333]: info: CoreStateMachine::pushState Dec 30 06:19:46 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:46 volumio volumio[18333]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:46 volumio volumio[18333]: info: Setting Device type: Raspberry PI Dec 30 06:19:47 volumio volumio[18333]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:47 volumio volumio[18333]: info: CoreStateMachine::pushState Dec 30 06:19:47 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:47 volumio volumio[18333]: info: Completed loading Core Plugins Dec 30 06:19:47 volumio volumio[18333]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:47 volumio sudo[18682]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 06:19:47 volumio sudo[18682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-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 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-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 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-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 06:19:47 volumio volumio[18333]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:47 volumio volumio[18333]: info: Discovery: Found device Volumio Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:47 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:47 volumio volumio[18333]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:19:47 volumio volumio[18333]: info: Discovery: Found device Volumio Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:47 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-06:00" level=info msg="zeroconf server listening on port 44707" Dec 30 06:19:47 volumio volumio[18333]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:47 volumio volumio[18333]: info: Reading ALSA contributions from plugins. Dec 30 06:19:47 volumio sudo[18682]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:47 volumio volumio[18333]: info: Upmpdcli Daemon Started Dec 30 06:19:47 volumio volumio[18333]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:47 volumio volumio[18333]: info: Output device has changed, restarting MPD Dec 30 06:19:47 volumio volumio[18333]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:47 volumio sudo[18685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:47 volumio sudo[18685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:47 volumio sudo[18685]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:47 volumio volumio[18333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:47 volumio sudo[18687]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:47 volumio volumio[18333]: info: ___________ START PLUGINS ___________ Dec 30 06:19:47 volumio sudo[18687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:47 volumio volumio[18333]: info: ControllerMpd::onStart: Initializing MPD Dec 30 06:19:47 volumio volumio[18333]: info: Creating MPD Configuration file Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-06:00" level=debug msg="obtained new client token: AAANcr+qfhYRFxjkpAqXXDjUbzse1QKSgaQz5qNvweIjqxjAt9FyXhuTVGWrnOnOMAN9maQ0l5SYsPJRqnRL4KWQpoTlM0cEjU95f+kQNB64ErK4xcxN5/Q5YlIlwK7VAZE8LNVEOAVfY9KIO9C3n/GLphq+ULaBtQyj8bySox7yDgaDK2WzaPzd+wlsr5i4lnTfzfru8BcR30tsatFjYTAWbvGKVvRxN5sod7DpgQTPn3+/8F6bHbU=" Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187223] CoreMusicLibrary::Adding element Media Servers Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 06:19:47 volumio sudo[18695]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:47 volumio sudo[18695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:47 volumio sudo[18697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:47 volumio sudo[18697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:47 volumio sudo[18695]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:47 volumio volumio[18333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-06:00" level=debug msg="completed challenge" Dec 30 06:19:47 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:47 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:47 volumio systemd[1]: mpd.service: Consumed 4.643s CPU time. Dec 30 06:19:47 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:47 volumio volumio[18333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187349] CoreMusicLibrary::Adding element Last_100 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:47 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187355] CoreMusicLibrary::Adding element Webradio Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:47 volumio volumio[18333]: info: Initializing BBC Radios Dec 30 06:19:47 volumio go-librespot[18665]: time="2025-12-30T06:19:47-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 06:19:47 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:47 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187443] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187456] CoreMusicLibrary::Adding element SoundCloud Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: info: Creating Spotify config file Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:47 volumio sudo[18722]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:47 volumio sudo[18722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:47 volumio sudo[18722]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:47 volumio volumio[18333]: info: [squeezelite_mc] Starting proxy server... Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187807] CoreMusicLibrary::Adding element YouTube2 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187826] CoreMusicLibrary::Adding element YouTube Music Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187837] CoreMusicLibrary::Adding element Podcast Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Podcast Dec 30 06:19:47 volumio volumio[18333]: info: Loading i18n strings for locale en Dec 30 06:19:47 volumio volumio[18333]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:19:47 volumio volumio[18333]: Updating browse sources language Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Podcast Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Podcast Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:47 volumio volumio[18333]: info: [1767097187884] CoreMusicLibrary::Adding element Volusonic Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Podcast Dec 30 06:19:47 volumio volumio[18333]: Cannot find translation for source Volusonic Dec 30 06:19:47 volumio volumio[18333]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 06:19:47 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 06:19:47 volumio volumio[18333]: info: Volumio Calling Home Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Proxy server started on port 44929 Dec 30 06:19:48 volumio volumio[18333]: info: Preparing to generate the ALSA configuration file Dec 30 06:19:48 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.83.122 Dec 30 06:19:48 volumio avahi-daemon[664]: Registering new address record for 169.254.83.122 on eth0.IPv4. Dec 30 06:19:48 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:48 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:48 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:48 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:19:48 volumio volumio[18333]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:19:48 volumio volumio[18333]: info: Reading ALSA contributions from plugins. Dec 30 06:19:48 volumio volumio[18333]: info: MPD Permissions set Dec 30 06:19:48 volumio volumio[18333]: info: MPD Permissions set Dec 30 06:19:48 volumio volumio[18333]: info: Spotify config file written Dec 30 06:19:48 volumio sudo[18748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 06:19:48 volumio sudo[18748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:48 volumio volumio[18333]: 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 06:19:48 volumio volumio[18333]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:19:48 volumio volumio[18333]: info: CoreStateMachine::pushState Dec 30 06:19:48 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::volumioPushState Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Server discovery started Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Player finder started Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 06:19:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:48 volumio go-librespot[18750]: go-librespot daemon starting... Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:48 volumio volumio[18333]: info: No need to fix Spotify hosts Dec 30 06:19:48 volumio sudo[18748]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=debug msg="app state loaded" Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:48 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.83.122 Dec 30 06:19:48 volumio volumio[18333]: 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 06:19:48 volumio volumio[18333]: info: Volumio called home Dec 30 06:19:48 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.83.122 Dec 30 06:19:48 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.83.122 Dec 30 06:19:48 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:48 volumio avahi-daemon[664]: Withdrawing address record for 169.254.83.122 on eth0. Dec 30 06:19:48 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:48 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:48 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:48 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 06:19:48 volumio volumio[18333]: 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 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-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 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-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 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-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 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=info msg="zeroconf server listening on port 46711" Dec 30 06:19:48 volumio volumio[18333]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:48 volumio volumio[18333]: SPOTIFY: BQDPGbHg3yf8hePB0H2iGyVVgjDu4-MPChTgDffUMxt5oxOMn0_Bb3BQwYnsPXa1ZGNrJEVHMx3aNbzwRjP1nFjUJiOSmrRujhMutCs_mIREJreb7hPBByLprBxuTW1i80drVSh82VX55sT3Hqaglpq4aWgs4HW0k2caA4Db9FtvhZlfTJES13rU26dXzsE_2Y0pWu0WLCXLD9ybpGEduENDLXdVrMpjDsJduQk Dec 30 06:19:48 volumio volumio[18333]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:19:48 volumio volumio[18333]: info: New Spotify access token = BQDPGbHg3yf8hePB0H2iGyVVgjDu4-MPChTgDffUMxt5oxOMn0_Bb3BQwYnsPXa1ZGNrJEVHMx3aNbzwRjP1nFjUJiOSmrRujhMutCs_mIREJreb7hPBByLprBxuTW1i80drVSh82VX55sT3Hqaglpq4aWgs4HW0k2caA4Db9FtvhZlfTJES13rU26dXzsE_2Y0pWu0WLCXLD9ybpGEduENDLXdVrMpjDsJduQk Dec 30 06:19:48 volumio volumio[18333]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 06:19:48 volumio sudo[18803]: 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 06:19:48 volumio sudo[18803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:48 volumio sudo[18803]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:48 volumio volumio[18333]: info: Starting Shairport Sync Dec 30 06:19:48 volumio volumio[18333]: info: Starting Shairport Sync Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=debug msg="obtained new client token: AADoU3ZSRbNgNmZFi5MTiIJDXn3gUKrvR52hzL6BS+QPdun0PFilRjtEtawppOucmAaUwHTN5G8pEvrec2KX1rNQ3MQEjcDjgNbBVkNqoqDjQg7SkKCEZANbp6a0p/cabftzzswmbPz8jjVV18CKafBtRllburMFH2qGnAoxhk5E/hexPIdyL4i+qMPMR+zR4wxjsdaE6nst9smQkzPIlvqizd9SLX1qrkiztxK49EUggggbWF22O1xaPQ==" Dec 30 06:19:48 volumio volumio[18333]: info: Starting Shairport Sync Dec 30 06:19:48 volumio sudo[18806]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:48 volumio sudo[18806]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:48 volumio sudo[18808]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:48 volumio sudo[18808]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:48 volumio volumio[18333]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 06:19:48 volumio go-librespot[18763]: time="2025-12-30T06:19:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:48 volumio sudo[18810]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:48 volumio sudo[18810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio volumio[18333]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:19:49 volumio volumio[18333]: info: Output device has changed, restarting MPD Dec 30 06:19:49 volumio go-librespot[18763]: time="2025-12-30T06:19:49-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:49 volumio go-librespot[18763]: time="2025-12-30T06:19:49-06:00" level=debug msg="completed challenge" Dec 30 06:19:49 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:49 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:49 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:49 volumio systemd[1]: shairport-sync.service: Consumed 2.095s CPU time. Dec 30 06:19:49 volumio sudo[18816]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 06:19:49 volumio sudo[18816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio volumio[18333]: info: Output device has changed, restarting Shairport Sync Dec 30 06:19:49 volumio go-librespot[18763]: time="2025-12-30T06:19:49-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:49 volumio sudo[18818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:19:49 volumio sudo[18818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio sudo[18816]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio sudo[18818]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio sudo[18822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:19:49 volumio sudo[18822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:19:49 volumio volumio[18333]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:19:49 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:49 volumio sudo[18808]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio sudo[18810]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:49 volumio sudo[18806]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:19:49 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:19:49 volumio systemd[1]: mpd.service: Consumed 1.588s CPU time. Dec 30 06:19:49 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:19:49 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:19:49 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:19:49 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:19:49 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:19:49 volumio volumio[18333]: info: MPD Permissions set Dec 30 06:19:49 volumio volumio[18333]: info: Shairport-Sync Started Dec 30 06:19:49 volumio volumio[18333]: Error adding Membership: Error: addMembership EINVAL Dec 30 06:19:49 volumio volumio[18333]: info: Shairport-Sync Started Dec 30 06:19:49 volumio volumio[18333]: info: Shairport-Sync Started Dec 30 06:19:49 volumio volumio[18333]: 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 06:19:49 volumio sudo[18853]: 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 06:19:49 volumio sudo[18853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio sudo[18853]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio sudo[18856]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:19:49 volumio sudo[18856]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::volumioGetState Dec 30 06:19:49 volumio volumio[18333]: info: CorePlayQueue::getTrack 0 Dec 30 06:19:49 volumio sudo[18849]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:19:49 volumio volumio[18333]: info: Starting Shairport Sync Dec 30 06:19:49 volumio sudo[18849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:19:49 volumio sudo[18849]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:49 volumio systemd[1]: Reloading. Dec 30 06:19:49 volumio sudo[18865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:19:49 volumio sudo[18865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:49 volumio volumio[18333]: 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 06:19:49 volumio volumio[18333]: info: Spotify Successfully logged in Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:19:49 volumio volumio[18333]: info: [1767097189988] CoreMusicLibrary::Adding element Spotify Dec 30 06:19:49 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:19:49 volumio volumio[18333]: Cannot find translation for source Bandcamp Discover Dec 30 06:19:49 volumio volumio[18333]: Cannot find translation for source SoundCloud Dec 30 06:19:49 volumio volumio[18333]: Cannot find translation for source YouTube2 Dec 30 06:19:49 volumio volumio[18333]: Cannot find translation for source YouTube Music Dec 30 06:19:49 volumio volumio[18333]: Cannot find translation for source Podcast Dec 30 06:19:50 volumio volumio[18333]: Cannot find translation for source Volusonic Dec 30 06:19:50 volumio volumio[18333]: Cannot find translation for source Spotify Dec 30 06:19:50 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:50 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:50 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:19:50 volumio volumio[18333]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:19:51 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:19:51 volumio volumio[18333]: info: go-librespot daemon successfully initialized Dec 30 06:19:52 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 06:19:52 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 06:19:52 volumio sudo[18856]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:52 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:52 volumio sudo[18886]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:52 volumio sudo[18886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Dec 30 06:19:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:52 volumio sudo[18886]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:52 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 06:19:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:19:52 volumio go-librespot[18888]: go-librespot daemon starting... Dec 30 06:19:53 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:19:53 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:53 volumio systemd[1]: shairport-sync.service: Consumed 1.499s CPU time. Dec 30 06:19:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:19:53 volumio sudo[18891]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 06:19:53 volumio sudo[18891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:53 volumio sudo[18865]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:53 volumio volumio[18333]: info: Shairport-Sync Started Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="app state loaded" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:53 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:53 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 06:19:53 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:53 volumio sudo[18891]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-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 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-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 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=info msg="zeroconf server listening on port 43725" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="obtained new client token: AABzCWK/MWj0+lNQIQ7ownKNx3HD+1Fu5BZOJo6VcxTTQHOY32pWXerQpRftcnKra8cCvRBfMMWVxVW3oBeovLQtspc3qxLawOVOEhoQ2KGfMjadtJZsRtqyFXJMmldQ7JMh27QiXGT9zbX5qDB4McORy06D5/LWuhV5Fo9xSWtva0JnjWwCBSNo5r5+ROsyRXAAZSlbrHndudP5H1RRWPV5wmqKkh7B0TvwYVlml4DG02ve8V18sgIS3Q==" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=debug msg="completed challenge" Dec 30 06:19:53 volumio go-librespot[18890]: time="2025-12-30T06:19:53-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 06:19:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:53 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:53 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.59.199 Dec 30 06:19:53 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:53 volumio avahi-daemon[664]: Registering new address record for 169.254.59.199 on eth0.IPv4. Dec 30 06:19:53 volumio sudo[18915]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:53 volumio sudo[18915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:53 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:53 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:53 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:54 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.59.199 Dec 30 06:19:54 volumio sudo[18915]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:54 volumio volumio[18333]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 06:19:54 volumio sudo[18935]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 06:19:54 volumio sudo[18935]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:54 volumio sudo[18935]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:54 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 06:19:54 volumio sudo[18938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 06:19:54 volumio sudo[18938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:54 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 06:19:54 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 06:19:54 volumio sudo[18938]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:54 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.59.199 Dec 30 06:19:54 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.59.199 Dec 30 06:19:54 volumio avahi-daemon[664]: Withdrawing address record for 169.254.59.199 on eth0. Dec 30 06:19:54 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:19:54 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:19:54 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:54 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:54 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:54 volumio volumio[18333]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:54 volumio volumio[18333]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:55 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:55 volumio sudo[18961]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:55 volumio sudo[18961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:55 volumio sudo[18961]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:55 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:55 volumio sudo[18964]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:55 volumio sudo[18964]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:55 volumio sudo[18964]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:56 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:56 volumio sudo[18967]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:56 volumio sudo[18967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:56 volumio sudo[18967]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:56 volumio volumio-remote-updater[702]: [2025-12-30 06:19:56] [connect] Successful connection Dec 30 06:19:56 volumio volumio-remote-updater[702]: [2025-12-30 06:19:56] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767097196 101 Dec 30 06:19:56 volumio volumio[18333]: 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 06:19:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Dec 30 06:19:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:19:57 volumio go-librespot[18969]: go-librespot daemon starting... Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="app state loaded" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="stored credentials not found" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:19:57 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:57 volumio sudo[18977]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:57 volumio sudo[18977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:57 volumio sudo[18977]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-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 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-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 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=info msg="zeroconf server listening on port 44261" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="obtained new client token: AABZgzg0nvmsp3ndUIvoP6M4xJnIvC/PV/RUYeIWmSUc0COFq8+T+niE8uQZNAHDemVXlUcCMEvXNt1ohdBkGlC9JOO3QI6V0BfyLW6guEIZAWcZFQ0LWhP9g2abrKpNK6sjqx5kJWa92Cz6DYFWke7BkIHqhfJd0DKV2zWpBhNzinauAd3UcXURVu4Ghn687uqtfwPwwUjvVx9P2EYpLlZErdzcEjRlyiXkdWFlSV34TNSMKPVGjauu+Q==" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="completed keyexchange" Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=debug msg="completed challenge" Dec 30 06:19:57 volumio mpd[18884]: 2025-12-30T06:19:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 06:19:57 volumio go-librespot[18970]: time="2025-12-30T06:19:57-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 06:19:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:19:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:19:57 volumio volumio[18333]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 06:19:57 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 06:19:57 volumio sudo[18697]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:57 volumio sudo[18687]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:57 volumio sudo[18983]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 06:19:57 volumio sudo[18983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:19:57 volumio sudo[18822]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:57 volumio sudo[18983]: pam_unix(sudo:session): session closed for user root Dec 30 06:19:57 volumio volumio[18333]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:57 volumio volumio[18333]: assert.ok(self.idling) Dec 30 06:19:57 volumio volumio[18333]: error: The expression evaluated to a falsy value: Dec 30 06:19:57 volumio volumio[18333]: assert.ok(self.idling) Dec 30 06:19:57 volumio volumio[18333]: info: Initializing connection to go-librespot Websocket Dec 30 06:19:57 volumio volumio[18333]: info: Completed starting Core Plugins Dec 30 06:19:57 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:57 volumio volumio[18333]: info: ----- MyVolumio plugins startup ---- Dec 30 06:19:57 volumio volumio[18333]: info: ------------------------------------------- Dec 30 06:19:57 volumio volumio[18333]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 06:19:57 volumio volumio[18333]: info: MPD running with PID18884 Dec 30 06:19:57 volumio volumio[18333]: ,establishing connection Dec 30 06:19:57 volumio volumio[18333]: error: updateQueue error: null Dec 30 06:19:57 volumio volumio[18333]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:19:57 volumio volumio[18333]: error: MPD error: The expression evaluated to a falsy value: Dec 30 06:19:57 volumio volumio[18333]: assert.ok(self.idling) Dec 30 06:19:57 volumio volumio[18333]: error: The expression evaluated to a falsy value: Dec 30 06:19:57 volumio volumio[18333]: assert.ok(self.idling) Dec 30 06:19:57 volumio volumio[18333]: error: updateQueue error: null Dec 30 06:19:59 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:19:59 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.63.225 Dec 30 06:19:59 volumio avahi-daemon[664]: Registering new address record for 169.254.63.225 on eth0.IPv4. Dec 30 06:19:59 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:19:59 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:19:59 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:19:59 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.63.225 Dec 30 06:20:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Dec 30 06:20:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:00 volumio go-librespot[19021]: go-librespot daemon starting... Dec 30 06:20:00 volumio go-librespot[19022]: time="2025-12-30T06:20:00-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:00 volumio go-librespot[19022]: time="2025-12-30T06:20:00-06:00" level=debug msg="app state loaded" Dec 30 06:20:00 volumio go-librespot[19022]: time="2025-12-30T06:20:00-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:00 volumio go-librespot[19022]: time="2025-12-30T06:20:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:00 volumio sudo[19029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:20:00 volumio sudo[19029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:00 volumio sudo[19031]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:20:00 volumio sudo[19031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:00 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 06:20:00 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 06:20:00 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 06:20:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.63.225 Dec 30 06:20:00 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.63.225 Dec 30 06:20:00 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:00 volumio avahi-daemon[664]: Withdrawing address record for 169.254.63.225 on eth0. Dec 30 06:20:00 volumio volumio[18333]: info: Initializing connection to go-librespot Websocket Dec 30 06:20:00 volumio go-librespot[19022]: time="2025-12-30T06:20:00-06:00" level=debug msg="new websocket client" Dec 30 06:20:00 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:00 volumio volumio[18333]: info: Connection to go-librespot Websocket established Dec 30 06:20:00 volumio sudo[19048]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 06:20:00 volumio sudo[19048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:00 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 06:20:00 volumio sudo[19029]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:00 volumio sudo[19031]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:00 volumio mpd_monitor.sh[19034]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 06:20:00 volumio volumio[18333]: info: Successfully started MPD Monitor Dec 30 06:20:00 volumio volumio[18333]: info: Successfully started MPD Monitor Dec 30 06:20:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:01 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 06:20:01 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 06:20:01 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=info msg="zeroconf server listening on port 46585" Dec 30 06:20:01 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 06:20:01 volumio sudo[19048]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:01 volumio mpd_monitor.sh[19059]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 06:20:01 volumio volumio[18333]: info: Successfully started MPD Monitor Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=debug msg="obtained new client token: AAAv+QvSZR6DUKPaJS9YHPwjPFFbf3ntAO1mNJeUME44OOUS47Q5ikCla4XdBX91i0ewlP8XAHOedQu8iScLjgWK6HEgLIBKV8gnxTwgs8h/M1c2R5WU4kpcUJ8btBuw9id5CMxvKvXoW47gaptzg9XkdUCeVc3nvUCwpqrodyvMMoaryKrOyBcCGDCPrGVzJnf/LUxa21Q0WMwJw7VvA7zi/WNYvYsSCE/JdS0aHcg14GIkPgyWa94=" Dec 30 06:20:01 volumio go-librespot[19022]: time="2025-12-30T06:20:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:03 volumio go-librespot[19022]: time="2025-12-30T06:20:03-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:03 volumio go-librespot[19022]: time="2025-12-30T06:20:03-06:00" level=debug msg="completed challenge" Dec 30 06:20:03 volumio go-librespot[19022]: time="2025-12-30T06:20: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 06:20:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:03 volumio volumio[18333]: info: Connection to go-librespot Websocket closed Dec 30 06:20:03 volumio volumio[18333]: info: Getting Spotify volume Dec 30 06:20:04 volumio volumio[18333]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:20:04 volumio volumio[18333]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 06:20:04 volumio volumio[18333]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 06:20:04 volumio volumio[18333]: errno: -111, Dec 30 06:20:04 volumio volumio[18333]: code: 'ECONNREFUSED', Dec 30 06:20:04 volumio volumio[18333]: syscall: 'connect', Dec 30 06:20:04 volumio volumio[18333]: address: '127.0.0.1', Dec 30 06:20:04 volumio volumio[18333]: port: 9879, Dec 30 06:20:04 volumio volumio[18333]: response: undefined Dec 30 06:20:04 volumio volumio[18333]: } Dec 30 06:20:04 volumio volumio[18333]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:20:05 volumio sudo[19079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:19' Dec 30 06:20:05 volumio sudo[19079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:05 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:20:05 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.167.52 Dec 30 06:20:05 volumio avahi-daemon[664]: Registering new address record for 169.254.167.52 on eth0.IPv4. Dec 30 06:20:05 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:06 volumio sudo[19079]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:06 volumio volumio-remote-updater[702]: [2025-12-30 06:20:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 06:20:06 volumio volumio-remote-updater[702]: [2025-12-30 06:20:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 06:20:06 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:06 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 06:20:06 volumio systemd[1]: volumio.service: Consumed 50.139s CPU time. Dec 30 06:20:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:20:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:20:06 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 397. Dec 30 06:20:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 06:20:06 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 06:20:06 volumio systemd[1]: volumio.service: Consumed 50.139s CPU time. Dec 30 06:20:06 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 06:20:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 06:20:06 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.167.52 Dec 30 06:20:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Dec 30 06:20:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:06 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.167.52 Dec 30 06:20:06 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.167.52 Dec 30 06:20:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:06 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:06 volumio avahi-daemon[664]: Withdrawing address record for 169.254.167.52 on eth0. Dec 30 06:20:06 volumio go-librespot[19123]: go-librespot daemon starting... Dec 30 06:20:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:06 volumio go-librespot[19126]: time="2025-12-30T06:20:06-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:06 volumio go-librespot[19126]: time="2025-12-30T06:20:06-06:00" level=debug msg="app state loaded" Dec 30 06:20:06 volumio go-librespot[19126]: time="2025-12-30T06:20:06-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:06 volumio go-librespot[19126]: time="2025-12-30T06:20:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:06 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-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 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-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 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-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 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-06:00" level=info msg="zeroconf server listening on port 36461" Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-06:00" level=debug msg="obtained new client token: AADI9Mhj6ZP2fU6AnM97YIof4b25J7w309/MmWF1BqTmjS1ryzcmOnfNCjMiZLy+KYAQpZM6I8InJOVCibZTNViooPPjaxG8RC5Z3qpfiZ8HdHi9ACYDnwA+6fwkHB5sRCmR4Pn7qAP4uQm8hJbnqI+1mcv6usxaubW3keLybZKSHq6jSSlrARr83/inHNOZ9Nl+S42YCS7dAF/g1MmDsLnklgQw1n7zn+rng43+RXra6p359sHyE/A=" Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-06:00" level=debug msg="completed challenge" Dec 30 06:20:07 volumio go-librespot[19126]: time="2025-12-30T06:20:07-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 06:20:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:08 volumio volumio[19108]: info: ------------------------------------------- Dec 30 06:20:08 volumio volumio[19108]: info: ----- Volumio3 ---- Dec 30 06:20:08 volumio volumio[19108]: info: ------------------------------------------- Dec 30 06:20:08 volumio volumio[19108]: info: ----- System startup ---- Dec 30 06:20:08 volumio volumio[19108]: info: ------------------------------------------- Dec 30 06:20:09 volumio volumio[19108]: info: MYVOLUMIO Environment detected Dec 30 06:20:09 volumio volumio[19108]: info: Plugin folders cleanup Dec 30 06:20:09 volumio volumio[19108]: info: Scanning into folder /volumio/app/plugins/ Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category audio_interface Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category miscellanea Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category music_service Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category plugins.json Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category system_controller Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category user_interface Dec 30 06:20:09 volumio volumio[19108]: info: Scanning into folder /data/plugins/ Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category audio_interface Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category music_service Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category system_controller Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category system_hardware Dec 30 06:20:09 volumio volumio[19108]: info: Scanning category user_interface Dec 30 06:20:09 volumio volumio[19108]: info: Plugin folders cleanup completed Dec 30 06:20:09 volumio volumio[19108]: info: ------------------------------------------- Dec 30 06:20:09 volumio volumio[19108]: info: ----- Core plugins startup ---- Dec 30 06:20:09 volumio volumio[19108]: info: ------------------------------------------- Dec 30 06:20:09 volumio volumio[19108]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 06:20:09 volumio volumio[19108]: info: Adding plugin upnp to MyMusic Plugins Dec 30 06:20:09 volumio volumio[19108]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 06:20:09 volumio volumio[19108]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 06:20:09 volumio volumio[19108]: info: Loading plugins from folder /data/plugins/ Dec 30 06:20:09 volumio volumio[19108]: info: Loading plugin "system"... Dec 30 06:20:09 volumio volumio[19108]: info: Loading plugin "appearance"... Dec 30 06:20:09 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:20:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Dec 30 06:20:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:10 volumio volumio[19108]: info: Loading plugin "network"... Dec 30 06:20:10 volumio volumio[19108]: info: Refreshing Cached IP Addresses Dec 30 06:20:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:10 volumio go-librespot[19161]: go-librespot daemon starting... Dec 30 06:20:10 volumio sudo[19163]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:20:10 volumio sudo[19163]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:10 volumio sudo[19163]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:10 volumio sudo[19165]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:20:10 volumio sudo[19165]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:10 volumio volumio[19108]: info: Loading plugin "services"... Dec 30 06:20:10 volumio go-librespot[19167]: time="2025-12-30T06:20:10-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:10 volumio go-librespot[19167]: time="2025-12-30T06:20:10-06:00" level=debug msg="app state loaded" Dec 30 06:20:10 volumio go-librespot[19167]: time="2025-12-30T06:20:10-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:10 volumio sudo[19165]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:10 volumio go-librespot[19167]: time="2025-12-30T06:20:10-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:10 volumio volumio[19108]: info: Loading plugin "alsa_controller"... Dec 30 06:20:10 volumio sudo[19178]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 06:20:10 volumio sudo[19178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:10 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:20:10 volumio volumio[19108]: info: Loading plugin "wizard"... Dec 30 06:20:10 volumio volumio[19108]: info: Loading plugin "networkfs"... Dec 30 06:20:10 volumio volumio[19108]: info: Starting Udev Watcher for removable devices Dec 30 06:20:11 volumio volumio[19108]: info: Ignoring mount for partition: boot Dec 30 06:20:11 volumio volumio[19108]: info: Ignoring mount for partition: volumio Dec 30 06:20:11 volumio volumio[19108]: info: Ignoring mount for partition: volumio_data Dec 30 06:20:11 volumio volumio[19108]: info: Mounting Device Wikipedia Dec 30 06:20:11 volumio sudo[19209]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 06:20:11 volumio sudo[19209]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-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 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-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 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-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 06:20:11 volumio sudo[19209]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:11 volumio volumio[19108]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:20:11 volumio volumio[19108]: dmesg(1) may have more information after failed mount system call. Dec 30 06:20:11 volumio volumio[19108]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 06:20:11 volumio volumio[19108]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 06:20:11 volumio volumio[19108]: dmesg(1) may have more information after failed mount system call. Dec 30 06:20:11 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:20:11 volumio volumio[19108]: info: Loading plugin "volumio_command_line_client"... Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-06:00" level=info msg="zeroconf server listening on port 38089" Dec 30 06:20:11 volumio volumio[19108]: info: Loading plugin "upnp"... Dec 30 06:20:11 volumio volumio[19108]: info: [1767097211180] Starting Upmpd Daemon Dec 30 06:20:11 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:20:11 volumio volumio[19108]: info: Loading plugin "my_music"... Dec 30 06:20:11 volumio volumio[19108]: info: Loading plugin "mpd"... Dec 30 06:20:11 volumio volumio-remote-updater[702]: [2025-12-30 06:20:11] [connect] Successful connection Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-06:00" level=debug msg="obtained new client token: AAADeWJ2sJ7/jYsSYU13gklzjSOVG+prGr+2adkKVFN7xDIDl+nUeiV6h8Lp66v5HKdAua7FjbYC/oOqZbPorzf2NoM5xKLnahbFsaQqRufkWlVihArUBFHmU21bhCYrZEC2dF2d3iNVgXFGs5ory+NHDVQTxQCd/UdY1lueEfXLSgbgD8/ej5bkYpbvGyk1N81fj+AsaDjwfS8kPqynvKl+hYyOQ2/HTq/gKJIzYj+I7DvY1U+ZKAQ=" Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:11 volumio sudo[19178]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-06:00" level=debug msg="completed challenge" Dec 30 06:20:11 volumio go-librespot[19167]: time="2025-12-30T06:20:11-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 06:20:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:11 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.200.33 Dec 30 06:20:11 volumio avahi-daemon[664]: Registering new address record for 169.254.200.33 on eth0.IPv4. Dec 30 06:20:11 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:11 volumio volumio[19108]: info: Loading plugin "upnp_browser"... Dec 30 06:20:11 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:20:12 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.200.33 Dec 30 06:20:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.200.33 Dec 30 06:20:13 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.200.33 Dec 30 06:20:13 volumio avahi-daemon[664]: Withdrawing address record for 169.254.200.33 on eth0. Dec 30 06:20:13 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:13 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "alarm-clock"... Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "airplay_emulation"... Dec 30 06:20:14 volumio volumio[19108]: info: Starting Shairport Sync Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "last_100"... Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "webradio"... Dec 30 06:20:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Dec 30 06:20:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:14 volumio go-librespot[19243]: go-librespot daemon starting... Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "i2s_dacs"... Dec 30 06:20:14 volumio volumio[19108]: info: I2S DAC not set, start Auto-detection Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "volumiodiscovery"... Dec 30 06:20:14 volumio go-librespot[19244]: time="2025-12-30T06:20:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:14 volumio go-librespot[19244]: time="2025-12-30T06:20:14-06:00" level=debug msg="app state loaded" Dec 30 06:20:14 volumio go-librespot[19244]: time="2025-12-30T06:20:14-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:14 volumio go-librespot[19244]: time="2025-12-30T06:20:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** For more information see Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:20:14 volumio volumio[19108]: *** WARNING *** For more information see Dec 30 06:20:14 volumio node[19108]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 06:20:14 volumio node[19108]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:20:14 volumio node[19108]: *** WARNING *** For more information see Dec 30 06:20:14 volumio node[19108]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 06:20:14 volumio node[19108]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 06:20:14 volumio node[19108]: *** WARNING *** For more information see Dec 30 06:20:14 volumio volumio[19108]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 06:20:14 volumio volumio[19108]: info: Discovery: Started advertising with name: Volumio Dec 30 06:20:14 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 06:20:14 volumio volumio[19108]: info: Loading plugin "bandcamp"... Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-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 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-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 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-06:00" level=info msg="zeroconf server listening on port 35769" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-06:00" level=debug msg="obtained new client token: AABEH6fKtn3W4QLYeRgR3YhvK1qPiSi4hW2plRmp9vf7F/BZcMfBYYnVtprEWQK3ooHXri4xZV9LXf6RiGiUtSMoMtpRc158rxx0CHwhudeJgXuSe1rrXcUA8FCv5kqLTNaYDfulF7Q8aT2nco454vE8DksvPUSy+zpcmLahZoJ79peVoiMLdph4Itjrp9EL7+wie1FCMmFM3pZvv9cX2R27DaY+b7ry+Hd51xBVNdJk07uCLuNvFN8=" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-06:00" level=debug msg="completed challenge" Dec 30 06:20:15 volumio go-librespot[19244]: time="2025-12-30T06:20:15-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 06:20:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:16 volumio volumio[19108]: info: Plugin calmradio is not enabled Dec 30 06:20:16 volumio volumio[19108]: info: Loading plugin "soundcloud"... Dec 30 06:20:16 volumio volumio[19108]: info: Loading plugin "spop"... Dec 30 06:20:17 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.196.23 Dec 30 06:20:17 volumio avahi-daemon[664]: Registering new address record for 169.254.196.23 on eth0.IPv4. Dec 30 06:20:17 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.196.23 Dec 30 06:20:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Dec 30 06:20:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:18 volumio go-librespot[19270]: go-librespot daemon starting... Dec 30 06:20:18 volumio go-librespot[19271]: time="2025-12-30T06:20:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:18 volumio go-librespot[19271]: time="2025-12-30T06:20:18-06:00" level=debug msg="app state loaded" Dec 30 06:20:18 volumio go-librespot[19271]: time="2025-12-30T06:20:18-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:18 volumio go-librespot[19271]: time="2025-12-30T06:20:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:18 volumio volumio[19108]: info: Loading plugin "squeezelite_mc"... Dec 30 06:20:18 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.196.23 Dec 30 06:20:18 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.196.23 Dec 30 06:20:18 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:18 volumio avahi-daemon[664]: Withdrawing address record for 169.254.196.23 on eth0. Dec 30 06:20:18 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:18 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:18 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:18 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20: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 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20: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 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20: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 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20:19-06:00" level=info msg="zeroconf server listening on port 44261" Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20:19-06:00" level=debug msg="obtained new client token: AABc7fG0H6cHrv3cJ4FsawqwOoT341QQ30fHk0X2UDez4ooHzFJgzquapAhSMST/dAbT6o2cMrsqPm9xL3s0BaerfYttAzAmjxN8pjZTZ4Bi1eSs/28Ckooh99GEZd9ctCYafkGNO2LxgdONQpwrgcuxGpl/QoLpAYiZxdeNiSmbzGDPaOnR++4eBzlubu/Vnt6BiPh0nWs22OJSaaeqT/TnRQkNVa1D0eu6tydOmo+0XdVOidTxiDA=" Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20:19-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20:19-06:00" level=debug msg="completed challenge" Dec 30 06:20:19 volumio go-librespot[19271]: time="2025-12-30T06:20: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 06:20:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:19 volumio volumio[19108]: info: Loading plugin "youtube2"... Dec 30 06:20:20 volumio volumio[19108]: info: Loading plugin "ytcr"... Dec 30 06:20:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Dec 30 06:20:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:22 volumio go-librespot[19312]: go-librespot daemon starting... Dec 30 06:20:22 volumio go-librespot[19313]: time="2025-12-30T06:20:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:22 volumio go-librespot[19313]: time="2025-12-30T06:20:22-06:00" level=debug msg="app state loaded" Dec 30 06:20:22 volumio go-librespot[19313]: time="2025-12-30T06:20:22-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:22 volumio go-librespot[19313]: time="2025-12-30T06:20:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:22 volumio volumio[19108]: info: Loading plugin "ytmusic"... Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20: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 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20: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 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20: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 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20:23-06:00" level=info msg="zeroconf server listening on port 34549" Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20:23-06:00" level=debug msg="obtained new client token: AACidjb2DGy16GwiuY2abO414I+vmVisWVB1s0DCd5esvKKvXpYdUotxcjRkWcp8uZt/ZQT1z9fkU8/RrcixjgVyP+HLqyzvZzcEVyfgo5SFOp0XfJUBgqMmZKyXGqfjhwgJ9uhHplZG3PNjQjdJ1G02GEFV0nnEAlC9P+12KuvPi/GbjpSDMrgITym8NzhzigAf80Xgo137RuO5m9Jt7IO74Ds2ZBK9listTckWV9T9UcAbprqtJJc=" Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20:23-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20:23-06:00" level=debug msg="completed challenge" Dec 30 06:20:23 volumio go-librespot[19313]: time="2025-12-30T06:20: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 06:20:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:23 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.72.90 Dec 30 06:20:23 volumio avahi-daemon[664]: Registering new address record for 169.254.72.90 on eth0.IPv4. Dec 30 06:20:23 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:23 volumio volumio[19108]: info: Plugin now_playing is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "outputs"... Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "albumart"... Dec 30 06:20:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.90 Dec 30 06:20:23 volumio volumio[19108]: info: Plugin example_plugin is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "inputs"... Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "updater_comm"... Dec 30 06:20:23 volumio volumio-remote-updater[702]: [2025-12-30 06:20:23] [connect] Successful connection Dec 30 06:20:23 volumio volumio[19108]: info: Plugin mpdemulation is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "rest_api"... Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "websocket"... Dec 30 06:20:23 volumio volumio[19108]: info: Starting Socket.io Server version 1.7.4 Dec 30 06:20:23 volumio volumio[19108]: info: Plugin fusiondsp is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Plugin mpdoutput is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Plugin RoonBridge is not enabled Dec 30 06:20:23 volumio volumio[19108]: info: Loading plugin "podcast"... Dec 30 06:20:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.90 Dec 30 06:20:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.72.90 Dec 30 06:20:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.72.90 on eth0. Dec 30 06:20:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:24 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:24 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:24 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:24 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:24 volumio volumio[19108]: info: ControllerPodcast::constructor Dec 30 06:20:24 volumio volumio[19108]: info: Loading plugin "volusonic"... Dec 30 06:20:24 volumio volumio[19338]: Forking 3 albumart workers Dec 30 06:20:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Dec 30 06:20:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:26 volumio go-librespot[19394]: go-librespot daemon starting... Dec 30 06:20:26 volumio volumio[19366]: Starting albumart workers Dec 30 06:20:26 volumio go-librespot[19395]: time="2025-12-30T06:20:26-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:26 volumio go-librespot[19395]: time="2025-12-30T06:20:26-06:00" level=debug msg="app state loaded" Dec 30 06:20:26 volumio go-librespot[19395]: time="2025-12-30T06:20:26-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:26 volumio go-librespot[19395]: time="2025-12-30T06:20:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:26 volumio volumio[19108]: info: Applying required configuration parameters for plugin volusonic Dec 30 06:20:26 volumio volumio[19108]: info: Loading plugin "backup_restore"... Dec 30 06:20:26 volumio volumio[19364]: Starting albumart workers Dec 30 06:20:26 volumio volumio[19365]: Starting albumart workers Dec 30 06:20:27 volumio volumio[19108]: info: Applying required configuration parameters for plugin backup_restore Dec 30 06:20:27 volumio volumio[19108]: info: Plugin rpi_eeprom_config is not enabled Dec 30 06:20:27 volumio volumio[19108]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 06:20:27 volumio volumio[19108]: info: Loading plugin "scheduledrestart"... Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-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 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-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 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-06:00" level=info msg="zeroconf server listening on port 46801" Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-06:00" level=debug msg="obtained new client token: AABQweO8mDurhVCl4cnjDKusSnBHke5EN3stTUQlcrFJlnDcS7FmH4oBuyZn4RD9nJTIbqGi5YFvk4UnPUCsb2K99JEj6PVLKkMP1QTjmPXhhFqtrNEQ4MI+DkUOOfXQNvu4Bgf7pGq6NfNAUp+J6sFxKAoytJ4v0O2UkzhVSex5HIbrLXKaNJZ66+V5j9qTrUfWCZLlt0AV1P4+1SyD+FOz51KNMwsW0SJ/np6jKWDlMz6Fi2wCSlnQ+g==" Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:27 volumio volumio[19108]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 06:20:27 volumio volumio[19108]: info: Plugin Bluetoothremote is not enabled Dec 30 06:20:27 volumio volumio[19108]: info: Plugin music_services_shield is not enabled Dec 30 06:20:27 volumio volumio[19108]: info: Loading plugin "Systeminfo"... Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20:27-06:00" level=debug msg="completed challenge" Dec 30 06:20:27 volumio go-librespot[19395]: time="2025-12-30T06:20: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 06:20:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:28 volumio volumio[19108]: info: Plugin peppymeterbasic is not enabled Dec 30 06:20:28 volumio volumio[19108]: info: Loading plugin "peppyspectrum"... Dec 30 06:20:28 volumio volumio[19108]: info: Loading i18n strings for locale en Dec 30 06:20:28 volumio volumio[19108]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:20:28 volumio volumio[19108]: Updating browse sources language Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::initPlayerControls Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:20:28 volumio volumio[19108]: Express server listening on port 3000 Dec 30 06:20:28 volumio volumio[19108]: [Metrics] WebUI: 20s 429.11ms Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::resetVolumioState Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::getcurrentVolume Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:28 volumio sudo[19425]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 06:20:28 volumio sudo[19425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:28 volumio sudo[19427]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 06:20:28 volumio sudo[19427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:28 volumio sudo[19425]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:28 volumio sudo[19427]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:28 volumio volumio[19108]: info: Volumio Network Manager: Network status updated: 1 Dec 30 06:20:28 volumio volumio[19108]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::pushState Dec 30 06:20:28 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::volumioPushState Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::updateTrackBlock Dec 30 06:20:28 volumio volumio[19108]: info: CorePlayQueue::getTrackBlock Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:20:28 volumio volumio[19108]: info: Reloading queue from file Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::setRepeat null single undefined Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::pushState Dec 30 06:20:28 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::volumioPushState Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::setRandom null Dec 30 06:20:28 volumio volumio[19108]: info: CoreStateMachine::pushState Dec 30 06:20:28 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:28 volumio volumio[19108]: info: CoreCommandRouter::volumioPushState Dec 30 06:20:28 volumio volumio[19108]: info: Setting Device type: Raspberry PI Dec 30 06:20:29 volumio volumio[19108]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:20:29 volumio volumio[19108]: info: CoreStateMachine::pushState Dec 30 06:20:29 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioPushState Dec 30 06:20:29 volumio volumio[19108]: info: Completed loading Core Plugins Dec 30 06:20:29 volumio volumio[19108]: info: Preparing to generate the ALSA configuration file Dec 30 06:20:29 volumio sudo[19441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 06:20:29 volumio sudo[19441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:29 volumio volumio[19108]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:20:29 volumio volumio[19108]: info: Discovery: Found device Volumio Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioGetState Dec 30 06:20:29 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:29 volumio volumio[19108]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 06:20:29 volumio volumio[19108]: info: Discovery: Found device Volumio Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioGetState Dec 30 06:20:29 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:29 volumio volumio[19108]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:20:29 volumio volumio[19108]: info: Reading ALSA contributions from plugins. Dec 30 06:20:29 volumio sudo[19441]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:29 volumio volumio[19108]: info: Upmpdcli Daemon Started Dec 30 06:20:29 volumio volumio[19108]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:20:29 volumio volumio[19108]: info: Output device has changed, restarting MPD Dec 30 06:20:29 volumio volumio[19108]: info: Output device has changed, restarting Shairport Sync Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:29 volumio sudo[19444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:20:29 volumio sudo[19444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:29 volumio sudo[19444]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:29 volumio sudo[19446]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:20:29 volumio sudo[19446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:29 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.44.247 Dec 30 06:20:29 volumio avahi-daemon[664]: Registering new address record for 169.254.44.247 on eth0.IPv4. Dec 30 06:20:29 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:29 volumio volumio[19108]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:20:29 volumio volumio[19108]: info: ___________ START PLUGINS ___________ Dec 30 06:20:29 volumio volumio[19108]: info: ControllerMpd::onStart: Initializing MPD Dec 30 06:20:29 volumio volumio[19108]: info: Creating MPD Configuration file Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229231] CoreMusicLibrary::Adding element Media Servers Dec 30 06:20:29 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:29 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:29 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 06:20:29 volumio sudo[19469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:20:29 volumio sudo[19469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:29 volumio sudo[19469]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:29 volumio sudo[19472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:20:29 volumio sudo[19472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:29 volumio volumio[19108]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:29 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:20:29 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:20:29 volumio systemd[1]: mpd.service: Consumed 5.796s CPU time. Dec 30 06:20:29 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:20:29 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:20:29 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:20:29 volumio volumio[19108]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229362] CoreMusicLibrary::Adding element Last_100 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229365] CoreMusicLibrary::Adding element Webradio Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:20:29 volumio volumio[19108]: info: Initializing BBC Radios Dec 30 06:20:29 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:20:29 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.44.247 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229444] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229455] CoreMusicLibrary::Adding element SoundCloud Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: info: Creating Spotify config file Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:29 volumio sudo[19496]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:20:29 volumio sudo[19496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:20:29 volumio sudo[19496]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.44.247 Dec 30 06:20:29 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.44.247 Dec 30 06:20:29 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:29 volumio avahi-daemon[664]: Withdrawing address record for 169.254.44.247 on eth0. Dec 30 06:20:29 volumio volumio[19108]: info: [squeezelite_mc] Starting proxy server... Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229825] CoreMusicLibrary::Adding element YouTube2 Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:29 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:29 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:29 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229860] CoreMusicLibrary::Adding element YouTube Music Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229872] CoreMusicLibrary::Adding element Podcast Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Podcast Dec 30 06:20:29 volumio volumio[19108]: info: Loading i18n strings for locale en Dec 30 06:20:29 volumio volumio[19108]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 06:20:29 volumio volumio[19108]: Updating browse sources language Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Podcast Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Podcast Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:29 volumio volumio[19108]: info: [1767097229926] CoreMusicLibrary::Adding element Volusonic Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Podcast Dec 30 06:20:29 volumio volumio[19108]: Cannot find translation for source Volusonic Dec 30 06:20:29 volumio volumio[19108]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 06:20:29 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 06:20:29 volumio volumio[19108]: info: Volumio Calling Home Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Proxy server started on port 39315 Dec 30 06:20:30 volumio volumio[19108]: info: Preparing to generate the ALSA configuration file Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 06:20:30 volumio volumio[19108]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 06:20:30 volumio volumio[19108]: info: Reading ALSA contributions from plugins. Dec 30 06:20:30 volumio volumio[19108]: info: MPD Permissions set Dec 30 06:20:30 volumio volumio[19108]: info: MPD Permissions set Dec 30 06:20:30 volumio volumio[19108]: info: Spotify config file written Dec 30 06:20:30 volumio sudo[19523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 06:20:30 volumio sudo[19523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:30 volumio volumio[19108]: 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 06:20:30 volumio volumio[19108]: info: VolumeController:: Volume=100 Mute =false Dec 30 06:20:30 volumio volumio[19108]: info: CoreStateMachine::pushState Dec 30 06:20:30 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::volumioPushState Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Server discovery started Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Player finder started Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 06:20:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:30 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:30 volumio go-librespot[19527]: go-librespot daemon starting... Dec 30 06:20:30 volumio volumio[19108]: info: No need to fix Spotify hosts Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=debug msg="app state loaded" Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:30 volumio sudo[19523]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:30 volumio volumio[19108]: 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 06:20:30 volumio volumio[19108]: info: Volumio called home Dec 30 06:20:30 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 06:20:30 volumio volumio[19108]: 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 06:20:30 volumio volumio[19108]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:20:30 volumio volumio[19108]: SPOTIFY: BQBMswaSUlIP9SP37YQk8ucRU6O4n4mQw6FRLqRzv7btZ447kcqII_Z2c1Es3TjFfEUrGyYpTSqihuByqKIKY4ffxODs9qwJqRuDpuCp4RZECyp2vRkDjYjLcJQ5oI2-pj0Fz3Ze_FAgjGivusmhTNUhz6aLKT1vth4XsQW7M9g-ZD4W4iLO26NhKBiIELO77dQzCF4LZECC5_RcmIGfZLzlocucCHeF7gryz3Q Dec 30 06:20:30 volumio volumio[19108]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 06:20:30 volumio volumio[19108]: info: New Spotify access token = BQBMswaSUlIP9SP37YQk8ucRU6O4n4mQw6FRLqRzv7btZ447kcqII_Z2c1Es3TjFfEUrGyYpTSqihuByqKIKY4ffxODs9qwJqRuDpuCp4RZECyp2vRkDjYjLcJQ5oI2-pj0Fz3Ze_FAgjGivusmhTNUhz6aLKT1vth4XsQW7M9g-ZD4W4iLO26NhKBiIELO77dQzCF4LZECC5_RcmIGfZLzlocucCHeF7gryz3Q Dec 30 06:20:30 volumio volumio[19108]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-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 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-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 06:20:30 volumio sudo[19549]: 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 06:20:30 volumio sudo[19549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=info msg="zeroconf server listening on port 38837" Dec 30 06:20:30 volumio sudo[19549]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:30 volumio volumio[19108]: info: Starting Shairport Sync Dec 30 06:20:30 volumio volumio[19108]: info: Starting Shairport Sync Dec 30 06:20:30 volumio volumio[19108]: info: Starting Shairport Sync Dec 30 06:20:30 volumio sudo[19556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:20:30 volumio volumio[19108]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=debug msg="obtained new client token: AABp/iT1wgXqjmVHRti3zBMCu2p6yIS2gAenKy2xZKgOGlr1vCjkE7Sz8ImyAWGRGDUvrXoywFtuqdvoyFMvNyp/3+gE4hFex0EJSdXx3wJc/+zoPpj1DQBSXA1nPqw5YAaC1XXRRRJWGPnJ4Mit6qUkw9JnRswFL8idCah+Autf2G7nov5l2NtA7W5qh4bWbZgZPip6dovbE6ds3J2RCRZ8xa0lHRhAntdQHYv5tlOtC+MQ6qKAD5uM8Q==" Dec 30 06:20:30 volumio sudo[19554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:20:30 volumio sudo[19554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:30 volumio sudo[19552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:20:30 volumio sudo[19552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:30 volumio sudo[19556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:30 volumio go-librespot[19538]: time="2025-12-30T06:20:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:30 volumio sudo[19566]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 06:20:31 volumio sudo[19566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:31 volumio go-librespot[19538]: time="2025-12-30T06:20:31-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:31 volumio go-librespot[19538]: time="2025-12-30T06:20:31-06:00" level=debug msg="completed challenge" Dec 30 06:20:31 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:20:31 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:20:31 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:20:31 volumio systemd[1]: shairport-sync.service: Consumed 2.147s CPU time. Dec 30 06:20:31 volumio sudo[19566]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio volumio[19108]: info: Asound.conf file unchanged, so no further update is needed Dec 30 06:20:31 volumio volumio[19108]: info: Output device has changed, restarting MPD Dec 30 06:20:31 volumio go-librespot[19538]: time="2025-12-30T06:20: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 06:20:31 volumio volumio[19108]: info: Output device has changed, restarting Shairport Sync Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:31 volumio sudo[19581]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 06:20:31 volumio sudo[19581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:31 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:20:31 volumio sudo[19552]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:31 volumio sudo[19583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 06:20:31 volumio sudo[19583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:31 volumio sudo[19554]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio sudo[19556]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio sudo[19581]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio volumio[19108]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 06:20:31 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 06:20:31 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 06:20:31 volumio systemd[1]: mpd.service: Consumed 1.676s CPU time. Dec 30 06:20:31 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 06:20:31 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 06:20:31 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 06:20:31 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 06:20:31 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 06:20:31 volumio volumio[19108]: info: MPD Permissions set Dec 30 06:20:31 volumio volumio[19108]: info: Shairport-Sync Started Dec 30 06:20:31 volumio volumio[19108]: Error adding Membership: Error: addMembership EINVAL Dec 30 06:20:31 volumio volumio[19108]: info: Shairport-Sync Started Dec 30 06:20:31 volumio volumio[19108]: info: Shairport-Sync Started Dec 30 06:20:31 volumio volumio[19108]: 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 06:20:31 volumio sudo[19611]: 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 06:20:31 volumio sudo[19611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:31 volumio sudo[19611]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio volumio[19108]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio sudo[19614]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 06:20:31 volumio sudo[19614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:31 volumio sudo[19608]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 06:20:31 volumio sudo[19608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 06:20:31 volumio sudo[19608]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:31 volumio volumio[19108]: info: CoreCommandRouter::volumioGetState Dec 30 06:20:31 volumio volumio[19108]: info: CorePlayQueue::getTrack 0 Dec 30 06:20:32 volumio volumio[19108]: info: Starting Shairport Sync Dec 30 06:20:32 volumio volumio[19108]: 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 06:20:32 volumio volumio[19108]: info: Spotify Successfully logged in Dec 30 06:20:32 volumio systemd[1]: Reloading. Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 06:20:32 volumio volumio[19108]: info: [1767097232100] CoreMusicLibrary::Adding element Spotify Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source Bandcamp Discover Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source SoundCloud Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source YouTube2 Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source YouTube Music Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source Podcast Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source Volusonic Dec 30 06:20:32 volumio volumio[19108]: Cannot find translation for source Spotify Dec 30 06:20:32 volumio sudo[19624]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 06:20:32 volumio sudo[19624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 06:20:32 volumio volumio[19108]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 06:20:32 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 06:20:33 volumio volumio[19108]: info: go-librespot daemon successfully initialized Dec 30 06:20:34 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 06:20:34 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 06:20:34 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.247.60 Dec 30 06:20:34 volumio avahi-daemon[664]: Registering new address record for 169.254.247.60 on eth0.IPv4. Dec 30 06:20:34 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 06:20:35 volumio volumio[19108]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:20:35 volumio sudo[19614]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Dec 30 06:20:35 volumio volumio[19108]: Error: addMembership ENODEV Dec 30 06:20:35 volumio volumio[19108]: at Socket.addMembership (node:dgram:860:11) Dec 30 06:20:35 volumio volumio[19108]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Dec 30 06:20:35 volumio volumio[19108]: errno: -19, Dec 30 06:20:35 volumio volumio[19108]: code: 'ENODEV', Dec 30 06:20:35 volumio volumio[19108]: syscall: 'addMembership' Dec 30 06:20:35 volumio volumio[19108]: } Dec 30 06:20:35 volumio volumio[19108]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 06:20:35 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.247.60 Dec 30 06:20:35 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:35 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:35 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 06:20:35 volumio go-librespot[19670]: go-librespot daemon starting... Dec 30 06:20:35 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 06:20:35 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 06:20:35 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:20:35 volumio systemd[1]: shairport-sync.service: Consumed 1.527s CPU time. Dec 30 06:20:35 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.247.60 Dec 30 06:20:35 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.247.60 Dec 30 06:20:35 volumio avahi-daemon[664]: Withdrawing address record for 169.254.247.60 on eth0. Dec 30 06:20:35 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 06:20:35 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 06:20:35 volumio sudo[19624]: pam_unix(sudo:session): session closed for user root Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="app state loaded" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="stored credentials not found" Dec 30 06:20:35 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 06:20:35 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 06:20:35 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 06:20:35 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-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 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-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 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=info msg="zeroconf server listening on port 35413" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="obtained new client token: AADSsyIC0urarB/62XUDFcme1ZuH4rBKzgftXcKkc6d4QvwutFFsxbykCoQHjlh70OfPnTcXbBImQp4zWeIlLrnFKu9kBxOwkg0cjm+OJYr8sc1Tx/rbBLX4YvVOXDaCUtI/6nt6DNMT2TNmawTEI3BxJzLfAN9yNsP0DjOqyxM3PGM88I0gI72o7db9Ek0IyH84ti3/7FjqIKyOtdkafkR794nVkzdAteGmbJe9UpSBmuHSYsz41vFp7Q==" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="completed keyexchange" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-06:00" level=debug msg="completed challenge" Dec 30 06:20:35 volumio go-librespot[19672]: time="2025-12-30T06:20:35-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 06:20:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 06:20:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 06:20:36 volumio sudo[19712]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 06:19' Dec 30 06:20:36 volumio sudo[19712]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="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"