Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=debug msg="obtained new client token: AAB8CXn0mmLjzHv5TPDUaJwdsMdb5utOeyGpi8GBpAb77VPxZCpV1TenGEiNlvDw16W2UzRJqS+RhDa5UhY2X6AZhTVY6Qmwmw5uxjrSiQQcPFphKNZtqTe9znbI63w/VjWk0H4YN8XBIpcev6Q6D7CfVUat/X5as1++Lc0KM4UD4nvODVzaGbdBbLBbY94tU1d6Oi6TBTfuPmFwL//Qto3LtKSXAUD8+mpjyGOFF+2esohbYJ27/p0="
Dec 09 17:38:00 volumio volumio[3015]: info: Applying required configuration parameters for plugin backup_restore
Dec 09 17:38:00 volumio volumio[3015]: info: Plugin rpi_eeprom_config is not enabled
Dec 09 17:38:00 volumio volumio[3015]: info: Plugin rpi_eeprom_updater is not enabled
Dec 09 17:38:00 volumio volumio[3015]: info: Loading plugin "scheduledrestart"...
Dec 09 17:38:00 volumio volumio[3127]: Starting albumart workers
Dec 09 17:38:00 volumio volumio[3126]: Starting albumart workers
Dec 09 17:38:00 volumio volumio[3125]: Starting albumart workers
Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused"
Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=debug msg="completed challenge"
Dec 09 17:38:00 volumio volumio[3015]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 09 17:38:00 volumio volumio[3015]: info: Plugin Bluetoothremote is not enabled
Dec 09 17:38:00 volumio volumio[3015]: info: Plugin music_services_shield is not enabled
Dec 09 17:38:00 volumio volumio[3015]: info: Loading plugin "Systeminfo"...
Dec 09 17:38:00 volumio go-librespot[3156]: time="2025-12-09T17:38:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:38:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:00 volumio volumio[3015]: info: Plugin peppymeterbasic is not enabled
Dec 09 17:38:00 volumio volumio[3015]: info: Loading plugin "peppyspectrum"...
Dec 09 17:38:01 volumio volumio[3015]: info: Loading i18n strings for locale en
Dec 09 17:38:01 volumio volumio[3015]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 17:38:01 volumio volumio[3015]: Updating browse sources language
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::initPlayerControls
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: Express server listening on port 3000
Dec 09 17:38:01 volumio volumio[3015]:  [Metrics]  WebUI:  14s 502.72ms 
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::resetVolumioState
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::getcurrentVolume
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:01 volumio sudo[3201]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 17:38:01 volumio sudo[3201]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio sudo[3201]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:01 volumio sudo[3203]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 17:38:01 volumio sudo[3203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio sudo[3203]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:01 volumio volumio[3015]: info: Volumio Network Manager: Network status updated: 1
Dec 09 17:38:01 volumio volumio[3015]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::pushState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::updateTrackBlock
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrackBlock
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:01 volumio volumio[3015]: info: Reloading queue from file
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::setRepeat null single undefined
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::pushState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::setRandom null
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::pushState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:01 volumio volumio[3015]: info: Setting Device type: Raspberry PI
Dec 09 17:38:01 volumio volumio[3015]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:01 volumio volumio[3015]: info: CoreStateMachine::pushState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:01 volumio volumio[3015]: info: Completed loading Core Plugins
Dec 09 17:38:01 volumio volumio[3015]: info: Preparing to generate the ALSA configuration file
Dec 09 17:38:01 volumio sudo[3216]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 17:38:01 volumio sudo[3216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio volumio[3015]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 17:38:01 volumio volumio[3015]: info: Discovery: Found device Volumio
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 17:38:01 volumio volumio[3015]: info: Discovery: Found device Volumio
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:01 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:01 volumio volumio[3015]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 17:38:01 volumio volumio[3015]: info: Reading ALSA contributions from plugins.
Dec 09 17:38:01 volumio sudo[3216]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:01 volumio volumio[3015]: info: Upmpdcli Daemon Started
Dec 09 17:38:01 volumio volumio[3015]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 17:38:01 volumio volumio[3015]: info: Output device has changed, restarting MPD
Dec 09 17:38:01 volumio volumio[3015]: info: Output device has changed, restarting Shairport Sync
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:01 volumio sudo[3219]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:01 volumio sudo[3219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio sudo[3219]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:01 volumio sudo[3221]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:01 volumio sudo[3221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio volumio[3015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:01 volumio volumio[3015]: info: ___________ START PLUGINS ___________
Dec 09 17:38:01 volumio volumio[3015]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 17:38:01 volumio volumio[3015]: info: Creating MPD Configuration file
Dec 09 17:38:01 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:01 volumio sudo[3229]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:01 volumio sudo[3229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio sudo[3231]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:01 volumio sudo[3231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:01 volumio volumio[3015]: info: [1765323481953] CoreMusicLibrary::Adding element Media Servers
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:01 volumio sudo[3229]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:01 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:02 volumio volumio[3015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:02 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 17:38:02 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 17:38:02 volumio systemd[1]: mpd.service: Consumed 4.576s CPU time.
Dec 09 17:38:02 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 17:38:02 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:02 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 17:38:02 volumio volumio[3015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482060] CoreMusicLibrary::Adding element Last_100
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482064] CoreMusicLibrary::Adding element Webradio
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:38:02 volumio volumio[3015]: info: Initializing BBC Radios
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:02 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482139] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482154] CoreMusicLibrary::Adding element SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: info: Creating Spotify config file
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:02 volumio sudo[3257]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 17:38:02 volumio sudo[3257]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 17:38:02 volumio sudo[3257]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:02 volumio volumio[3015]: info: [squeezelite_mc] Starting proxy server...
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482505] CoreMusicLibrary::Adding element YouTube2
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482524] CoreMusicLibrary::Adding element YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482536] CoreMusicLibrary::Adding element Podcast
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Podcast
Dec 09 17:38:02 volumio volumio[3015]: info: Loading i18n strings for locale en
Dec 09 17:38:02 volumio volumio[3015]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 17:38:02 volumio volumio[3015]: Updating browse sources language
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Podcast
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Podcast
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:02 volumio volumio[3015]: info: [1765323482596] CoreMusicLibrary::Adding element Volusonic
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Podcast
Dec 09 17:38:02 volumio volumio[3015]: Cannot find translation for source Volusonic
Dec 09 17:38:02 volumio volumio[3015]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 17:38:02 volumio volumio[3015]: info: Volumio Calling Home
Dec 09 17:38:02 volumio volumio[3015]: info: [squeezelite_mc] Proxy server started on port 41107
Dec 09 17:38:02 volumio volumio[3015]: info: Preparing to generate the ALSA configuration file
Dec 09 17:38:02 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:02] [connect] Successful connection
Dec 09 17:38:02 volumio volumio[3015]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:02 volumio volumio[3015]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 17:38:02 volumio volumio[3015]: info: Reading ALSA contributions from plugins.
Dec 09 17:38:02 volumio volumio[3015]: info: MPD Permissions set
Dec 09 17:38:02 volumio volumio[3015]: info: MPD Permissions set
Dec 09 17:38:02 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765323482 101
Dec 09 17:38:02 volumio volumio[3015]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1
Dec 09 17:38:02 volumio volumio[3015]: info: Spotify config file written
Dec 09 17:38:02 volumio sudo[3267]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 17:38:02 volumio sudo[3267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:03 volumio volumio[3015]: 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 09 17:38:03 volumio volumio[3015]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:03 volumio volumio[3015]: info: CoreStateMachine::pushState
Dec 09 17:38:03 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Server discovery started
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Player finder started
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio go-librespot[3269]: go-librespot daemon starting...
Dec 09 17:38:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:03 volumio sudo[3267]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="app state loaded"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: No need to fix Spotify hosts
Dec 09 17:38:03 volumio volumio[3015]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3
Dec 09 17:38:03 volumio volumio[3015]: info: Volumio called home
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-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 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-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 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=info msg="zeroconf server listening on port 36235"
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 17:38:03 volumio volumio[3015]: 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 09 17:38:03 volumio volumio[3015]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 17:38:03 volumio volumio[3015]: SPOTIFY: BQDHtFBpUAKf1iDdxQsT6JoaWroi9i5y-tYsFqc2mBmnRgfVQBmvFOZ47kNSgfxy6hsM6jioHeZWkCOz3Tnfgq9y_zvCTiTPBArBD40IB7Ixmxy1jGVBa8_nCfr01QzdneA1N2viw5PvfLcuP19ikEZBBKBRr9avk8fFMX9mxLl0RYO4PUWikyLpP-RBZ7KuXWOqPXcYv4d8auCtiH0zrFrHEutVYVmNB85ct70
Dec 09 17:38:03 volumio volumio[3015]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 17:38:03 volumio volumio[3015]: info: New Spotify access token = BQDHtFBpUAKf1iDdxQsT6JoaWroi9i5y-tYsFqc2mBmnRgfVQBmvFOZ47kNSgfxy6hsM6jioHeZWkCOz3Tnfgq9y_zvCTiTPBArBD40IB7Ixmxy1jGVBa8_nCfr01QzdneA1N2viw5PvfLcuP19ikEZBBKBRr9avk8fFMX9mxLl0RYO4PUWikyLpP-RBZ7KuXWOqPXcYv4d8auCtiH0zrFrHEutVYVmNB85ct70
Dec 09 17:38:03 volumio volumio[3015]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 17:38:03 volumio volumio[3015]: info: Starting Shairport Sync
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="obtained new client token: AADC3WRjRI55ya6nVMV62oLI8z38i9dNlVSAxEXw0A19HgnUOFZP4ujgO+R9vQVeEXYxjinmA6g3YXDNeSlZAQJteXlLcOyK71oQuPf6ckvm84JC0sB0PAGgIUfOWlwl1hCOQwhUxTH9dk7x8ISlEm84DTuakhFe57RXV9yQC1ZyrxYmKw47LUdm8eZ7BzVZQsswJVDRrPoHzGIkXn7WjTngGcfCyJQKNgkNg8ru+aHXI4Kh7DJgmyNBhA=="
Dec 09 17:38:03 volumio volumio[3015]: info: Starting Shairport Sync
Dec 09 17:38:03 volumio volumio[3015]: info: Starting Shairport Sync
Dec 09 17:38:03 volumio sudo[3295]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:03 volumio sudo[3296]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:03 volumio sudo[3295]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3292]:  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 09 17:38:03 volumio sudo[3292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3298]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:03 volumio sudo[3298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3292]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38:03-06:00" level=debug msg="completed challenge"
Dec 09 17:38:03 volumio go-librespot[3274]: time="2025-12-09T17:38: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 09 17:38:03 volumio volumio[3015]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 17:38:03 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 17:38:03 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 17:38:03 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:03 volumio systemd[1]: shairport-sync.service: Consumed 1.970s CPU time.
Dec 09 17:38:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:03 volumio volumio[3015]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 17:38:03 volumio volumio[3015]: info: Output device has changed, restarting MPD
Dec 09 17:38:03 volumio volumio[3015]: info: Output device has changed, restarting Shairport Sync
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:03 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:03 volumio sudo[3305]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 17:38:03 volumio sudo[3305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3308]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:03 volumio sudo[3308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3308]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio sudo[3312]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:03 volumio sudo[3312]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:03 volumio sudo[3305]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:03 volumio volumio[3015]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:03 volumio sudo[3296]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio sudo[3295]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio sudo[3298]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:03 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 17:38:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 17:38:03 volumio systemd[1]: mpd.service: Consumed 1.598s CPU time.
Dec 09 17:38:03 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 17:38:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 17:38:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 17:38:04 volumio volumio[3015]: info: MPD Permissions set
Dec 09 17:38:04 volumio volumio[3015]: info: Shairport-Sync Started
Dec 09 17:38:04 volumio volumio[3015]: Error adding Membership: Error: addMembership EINVAL
Dec 09 17:38:04 volumio volumio[3015]: info: Shairport-Sync Started
Dec 09 17:38:04 volumio volumio[3015]: info: Shairport-Sync Started
Dec 09 17:38:04 volumio volumio[3015]: 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 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:04 volumio sudo[3340]:  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 09 17:38:04 volumio sudo[3340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:04 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:04 volumio sudo[3340]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:04 volumio sudo[3337]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 17:38:04 volumio sudo[3337]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 17:38:04 volumio sudo[3337]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:04 volumio volumio[3015]: info: Starting Shairport Sync
Dec 09 17:38:04 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 09 17:38:04 volumio sudo[3350]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:04 volumio sudo[3350]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:04 volumio sudo[3353]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 17:38:04 volumio sudo[3353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 17:38:04 volumio volumio[3015]: 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 09 17:38:04 volumio volumio[3015]: info: Spotify Successfully logged in
Dec 09 17:38:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 17:38:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:04 volumio volumio[3015]: info: [1765323484434] CoreMusicLibrary::Adding element Spotify
Dec 09 17:38:04 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source SoundCloud
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source YouTube2
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source YouTube Music
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source Podcast
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source Volusonic
Dec 09 17:38:04 volumio volumio[3015]: Cannot find translation for source Spotify
Dec 09 17:38:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:04 volumio systemd[1]: Reloading.
Dec 09 17:38:04 volumio volumio[3015]: info: [squeezelite_mc] Notification listener started
Dec 09 17:38:04 volumio volumio[3015]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 17:38:05 volumio volumio[3015]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 17:38:05 volumio volumio[3015]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 17:38:05 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:05 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:05 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:05 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:06 volumio volumio[3015]: info: go-librespot daemon successfully initialized
Dec 09 17:38:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:38:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:38:06 volumio sudo[3350]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:06 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:06 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:06 volumio sudo[3353]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:06 volumio volumio[3015]: info: Shairport-Sync Started
Dec 09 17:38:06 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:06 volumio sudo[3388]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:06 volumio sudo[3388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31.
Dec 09 17:38:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:06 volumio go-librespot[3390]: go-librespot daemon starting...
Dec 09 17:38:06 volumio go-librespot[3391]: time="2025-12-09T17:38:06-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:06 volumio go-librespot[3391]: time="2025-12-09T17:38:06-06:00" level=debug msg="app state loaded"
Dec 09 17:38:06 volumio go-librespot[3391]: time="2025-12-09T17:38:06-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:06 volumio go-librespot[3391]: time="2025-12-09T17:38:06-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:06 volumio sudo[3388]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:06 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 17:38:06 volumio sudo[3398]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 17:38:06 volumio sudo[3398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:06 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 17:38:07 volumio volumio[3015]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 17:38:07 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:07 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:07 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 17:38:07 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38: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-gew4.spotify.com:80]"
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-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 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-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 09 17:38:07 volumio sudo[3398]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-06:00" level=info msg="zeroconf server listening on port 43355"
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-06:00" level=debug msg="obtained new client token: AADc7XPSbyVimqaOBP5K8iEwaWmsj5rHP1vbSnKVjFToAYeEWyJtdT7QP/a07jBJDmyxHEtY7ALiI7B9MhKSopKWSqQElQGM4lKhRZ5w2e8jEjqggoEMn/ETB9pDzDw74cD8KCXV6PBbpdK6CNRWk70dudcuBkwGMIfujhFpQTagxLYqPotec/5cx1QjYMpIBSGocBNfJky1Y2fbeS9PmBQppnUxJWBU/Fh4Jp2GkNy8gbITktVkVl0="
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38:07-06:00" level=debug msg="completed challenge"
Dec 09 17:38:07 volumio go-librespot[3391]: time="2025-12-09T17:38: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 09 17:38:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:07 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:07 volumio sudo[3402]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:07 volumio sudo[3402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:07 volumio sudo[3402]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:07 volumio volumio[3015]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 17:38:07 volumio sudo[3406]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 17:38:07 volumio sudo[3406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:07 volumio sudo[3406]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:07 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 17:38:07 volumio sudo[3409]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 17:38:07 volumio sudo[3409]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:08 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 17:38:08 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 17:38:08 volumio mpd[3349]: 2025-12-09T17:38:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 17:38:08 volumio sudo[3409]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:08 volumio volumio[3015]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 17:38:08 volumio volumio[3015]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 17:38:08 volumio volumio[3015]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 17:38:08 volumio volumio[3015]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 17:38:08 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 17:38:08 volumio sudo[3231]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:08 volumio sudo[3221]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:08 volumio sudo[3312]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:08 volumio volumio[3015]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 17:38:08 volumio volumio[3015]:   assert.ok(self.idling)
Dec 09 17:38:08 volumio volumio[3015]: error: The expression evaluated to a falsy value:
Dec 09 17:38:08 volumio volumio[3015]:   assert.ok(self.idling)
Dec 09 17:38:08 volumio volumio[3015]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 17:38:08 volumio volumio[3015]:   assert.ok(self.idling)
Dec 09 17:38:08 volumio volumio[3015]: error: The expression evaluated to a falsy value:
Dec 09 17:38:08 volumio volumio[3015]:   assert.ok(self.idling)
Dec 09 17:38:08 volumio volumio[3015]: info: MPD running with PID3349
Dec 09 17:38:08 volumio volumio[3015]:  ,establishing connection
Dec 09 17:38:08 volumio volumio[3015]: error: updateQueue error: null
Dec 09 17:38:08 volumio volumio[3015]: error: updateQueue error: null
Dec 09 17:38:08 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:08 volumio sudo[3420]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:08 volumio sudo[3420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:08 volumio sudo[3420]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:09 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:09 volumio sudo[3423]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:09 volumio sudo[3423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:09 volumio sudo[3423]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:09 volumio volumio[3015]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:09 volumio volumio[3015]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:09 volumio volumio[3015]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:09 volumio volumio[3015]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:09 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:09 volumio sudo[3440]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:09 volumio sudo[3440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:09 volumio sudo[3440]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:10 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:10 volumio sudo[3446]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:10 volumio sudo[3446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:10 volumio sudo[3446]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32.
Dec 09 17:38:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:10 volumio go-librespot[3448]: go-librespot daemon starting...
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=debug msg="app state loaded"
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-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 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-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 09 17:38:10 volumio go-librespot[3449]: time="2025-12-09T17:38:10-06:00" level=info msg="zeroconf server listening on port 44943"
Dec 09 17:38:10 volumio volumio[3015]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:10 volumio sudo[3457]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:10 volumio sudo[3457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:10 volumio sudo[3457]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:10 volumio volumio[3015]: info: Completed starting Core Plugins
Dec 09 17:38:10 volumio volumio[3015]: info: -------------------------------------------
Dec 09 17:38:10 volumio volumio[3015]: info: -----    MyVolumio plugins startup     ----
Dec 09 17:38:10 volumio volumio[3015]: info: -------------------------------------------
Dec 09 17:38:10 volumio volumio[3015]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 17:38:11 volumio go-librespot[3449]: time="2025-12-09T17:38:11-06:00" level=debug msg="obtained new client token: AADoESvrDqeRG80rLq5uQ1/ARvSBE8ySUuQpLJ9yJONxDCu/gNt8e73ZAN70pMNzNtj9b9BKeHa6c0mXKgNeQGcD76V9HclPzUD98T2dT6fpV+dtG3pCAXTigUX2i9XHwx+Df9Gtp4Dp3kuROgMSF2JDxFt4jMAOPC9uLLOWx41pIKq/R4IxEU1Lf/VguXOGzz0Kd/A4bpiOtcMeMI92/Y+tyrUeqdz4J3HbR88aVfsvYuMyFtJce9/GzQ=="
Dec 09 17:38:11 volumio go-librespot[3449]: time="2025-12-09T17:38:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:11 volumio go-librespot[3449]: time="2025-12-09T17:38:11-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:11 volumio go-librespot[3449]: time="2025-12-09T17:38:11-06:00" level=debug msg="completed challenge"
Dec 09 17:38:11 volumio go-librespot[3449]: time="2025-12-09T17:38: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 09 17:38:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:11 volumio sudo[3460]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:11 volumio sudo[3460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:11 volumio sudo[3462]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:11 volumio sudo[3462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:11 volumio sudo[3465]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:11 volumio sudo[3465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:11 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 17:38:11 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 17:38:11 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 17:38:11 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 17:38:11 volumio sudo[3462]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:11 volumio sudo[3465]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:11 volumio sudo[3460]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:11 volumio mpd_monitor.sh[3468]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 17:38:11 volumio volumio[3015]: info: Successfully started MPD Monitor
Dec 09 17:38:11 volumio volumio[3015]: info: Successfully started MPD Monitor
Dec 09 17:38:11 volumio volumio[3015]: info: Successfully started MPD Monitor
Dec 09 17:38:12 volumio volumio[3015]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:12 volumio volumio[3015]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33.
Dec 09 17:38:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:14 volumio go-librespot[3472]: go-librespot daemon starting...
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=debug msg="app state loaded"
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-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 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-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 09 17:38:14 volumio go-librespot[3473]: time="2025-12-09T17:38:14-06:00" level=info msg="zeroconf server listening on port 42871"
Dec 09 17:38:15 volumio go-librespot[3473]: time="2025-12-09T17:38:15-06:00" level=debug msg="obtained new client token: AADQKmjewLcSQWJRNQ00q3qEjRtz9n5dvIL+zb01urlkB2KbLIrhE/1TMkWWV1pmuH3zGsz2+Zb7xFoU6NwfqolqNa/bN76uwP3141d4FPV47y98PVoV7DEJpWfGqAK5J+akNZQ2deztcYzX2XM4la663FaqkLc3+kugou6pXCGw8GycbAha0MyzorbrJ1S45ZGtuUOGPJ+m/zhlE5uu9wGTa7LnKY/lBAkbmdQDH5JBjHbinHJ9YNY="
Dec 09 17:38:15 volumio go-librespot[3473]: time="2025-12-09T17:38:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:15 volumio go-librespot[3473]: time="2025-12-09T17:38:15-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:15 volumio go-librespot[3473]: time="2025-12-09T17:38:15-06:00" level=debug msg="completed challenge"
Dec 09 17:38:16 volumio volumio[3015]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:16 volumio go-librespot[3473]: time="2025-12-09T17:38:16-06:00" level=debug msg="new websocket client"
Dec 09 17:38:16 volumio volumio[3015]: info: Connection to go-librespot Websocket established
Dec 09 17:38:19 volumio volumio[3015]: info: Getting Spotify volume
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 17:38:19 volumio volumio[3015]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 17:38:20 volumio volumio[3015]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 17:38:20 volumio volumio[3015]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 17:38:20 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:20 volumio volumio[3015]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:20 volumio volumio[3015]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 17:38:20 volumio volumio[3015]: info: MyVolumio login type: Token
Dec 09 17:38:20 volumio volumio[3015]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 17:38:20 volumio volumio[3015]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 17:38:20 volumio go-librespot[3473]: time="2025-12-09T17:38:20-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 09 17:38:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:21 volumio volumio[3015]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 17:38:21 volumio volumio[3015]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 17:38:21 volumio volumio[3015]: info: Streaming services startup
Dec 09 17:38:21 volumio volumio[3015]: info: Starting Streaming Daemon
Dec 09 17:38:21 volumio sudo[3496]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 17:38:21 volumio sudo[3496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:21 volumio volumio[3015]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 17:38:21 volumio sudo[3496]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:21 volumio volumio[3015]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 17:38:21 volumio volumio[3015]: Error: socket hang up
Dec 09 17:38:21 volumio volumio[3015]:     at connResetException (node:internal/errors:720:14)
Dec 09 17:38:21 volumio volumio[3015]:     at Socket.socketOnEnd (node:_http_client:519:23)
Dec 09 17:38:21 volumio volumio[3015]:     at Socket.emit (node:events:526:35)
Dec 09 17:38:21 volumio volumio[3015]:     at endReadableNT (node:internal/streams/readable:1376:12)
Dec 09 17:38:21 volumio volumio[3015]:     at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 09 17:38:21 volumio volumio[3015]:   code: 'ECONNRESET',
Dec 09 17:38:21 volumio volumio[3015]:   response: undefined
Dec 09 17:38:21 volumio volumio[3015]: }
Dec 09 17:38:21 volumio volumio[3015]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 17:38:21 volumio sudo[3516]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 17:37'
Dec 09 17:38:21 volumio sudo[3516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:22 volumio sudo[3516]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:23 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 09 17:38:23 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 09 17:38:23 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:23 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 09 17:38:23 volumio systemd[1]: volumio.service: Consumed 44.475s CPU time.
Dec 09 17:38:23 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 17:38:23 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 17:38:23 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24703.
Dec 09 17:38:23 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 17:38:23 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 09 17:38:23 volumio systemd[1]: volumio.service: Consumed 44.475s CPU time.
Dec 09 17:38:23 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 09 17:38:23 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 17:38:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34.
Dec 09 17:38:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:23 volumio go-librespot[3554]: go-librespot daemon starting...
Dec 09 17:38:23 volumio go-librespot[3555]: time="2025-12-09T17:38:23-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:23 volumio go-librespot[3555]: time="2025-12-09T17:38:23-06:00" level=debug msg="app state loaded"
Dec 09 17:38:23 volumio go-librespot[3555]: time="2025-12-09T17:38:23-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:23 volumio go-librespot[3555]: time="2025-12-09T17:38:23-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-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 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-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 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-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 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-06:00" level=info msg="zeroconf server listening on port 45703"
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-06:00" level=debug msg="obtained new client token: AAAeisinBWIwepoiBtmYfhiimkS5FIMPnVlM1GP4hdaiQU+Sdj+8Is4IecIOMUzeZrMItXRo1Cq01WjdBnFrx31CFBrbRQ4vhGZgKaFUYWQjI4LXK9N0ui4P1EXkYyXJEgcZNWPo5gi0RackeFFU6DdrlwRqdt7kbP4D0I0T2RPuYZlvRaT/d/IVj6o98La95yratdTotH9WrW10ET/LOr8XhxYbe2W09hRZAE99uyV4hktvdnQ3DWw="
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-06:00" level=debug msg="completed challenge"
Dec 09 17:38:24 volumio go-librespot[3555]: time="2025-12-09T17:38:24-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 09 17:38:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:25 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:25 volumio volumio[3539]: info: -----            Volumio3              ----
Dec 09 17:38:25 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:25 volumio volumio[3539]: info: -----          System startup          ----
Dec 09 17:38:25 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:25 volumio volumio[3539]: info: MYVOLUMIO Environment detected
Dec 09 17:38:26 volumio volumio[3539]: info: Plugin folders cleanup
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning into folder /volumio/app/plugins/
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category audio_interface
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category miscellanea
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category music_service
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category plugins.json
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category system_controller
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category user_interface
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning into folder /data/plugins/
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category audio_interface
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category music_service
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category system_controller
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category system_hardware
Dec 09 17:38:26 volumio volumio[3539]: info: Scanning category user_interface
Dec 09 17:38:26 volumio volumio[3539]: info: Plugin folders cleanup completed
Dec 09 17:38:26 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:26 volumio volumio[3539]: info: -----      Core plugins startup        ----
Dec 09 17:38:26 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:26 volumio volumio[3539]: info: Loading plugins from folder /volumio/app/plugins/
Dec 09 17:38:26 volumio volumio[3539]: info: Adding plugin upnp to MyMusic Plugins
Dec 09 17:38:26 volumio volumio[3539]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 09 17:38:26 volumio volumio[3539]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 09 17:38:26 volumio volumio[3539]: info: Loading plugins from folder /data/plugins/
Dec 09 17:38:26 volumio volumio[3539]: info: Loading plugin "system"...
Dec 09 17:38:26 volumio volumio[3539]: info: Loading plugin "appearance"...
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "network"...
Dec 09 17:38:27 volumio volumio[3539]: info: Refreshing Cached IP Addresses
Dec 09 17:38:27 volumio sudo[3575]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 17:38:27 volumio sudo[3575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:27 volumio sudo[3577]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 17:38:27 volumio sudo[3577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:27 volumio sudo[3575]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:27 volumio sudo[3577]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "services"...
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "alsa_controller"...
Dec 09 17:38:27 volumio sudo[3588]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 09 17:38:27 volumio sudo[3588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:27 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "wizard"...
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "networkfs"...
Dec 09 17:38:27 volumio volumio[3539]: info: Starting Udev Watcher for removable devices
Dec 09 17:38:27 volumio volumio[3539]: info: Ignoring mount for partition: boot
Dec 09 17:38:27 volumio volumio[3539]: info: Ignoring mount for partition: volumio
Dec 09 17:38:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35.
Dec 09 17:38:27 volumio volumio[3539]: info: Ignoring mount for partition: volumio_data
Dec 09 17:38:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:27 volumio volumio[3539]: info: Mounting Device Wikipedia
Dec 09 17:38:27 volumio sudo[3615]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 09 17:38:27 volumio sudo[3615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:27 volumio go-librespot[3610]: go-librespot daemon starting...
Dec 09 17:38:27 volumio sudo[3615]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:27 volumio volumio[3539]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 17:38:27 volumio volumio[3539]:        dmesg(1) may have more information after failed mount system call.
Dec 09 17:38:27 volumio volumio[3539]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 09 17:38:27 volumio volumio[3539]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 17:38:27 volumio volumio[3539]:        dmesg(1) may have more information after failed mount system call.
Dec 09 17:38:27 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "volumio_command_line_client"...
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "upnp"...
Dec 09 17:38:27 volumio volumio[3539]: info: [1765323507536] Starting Upmpd Daemon
Dec 09 17:38:27 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "my_music"...
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="app state loaded"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "mpd"...
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=info msg="zeroconf server listening on port 37765"
Dec 09 17:38:27 volumio sudo[3588]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="obtained new client token: AADHR14md8hynnqQlkTpv+d4JLom9xI0nt6DPApkQUIkAz67mlY4Droug8yXZa0PupNj4B3ElVjb18VIQpvhjzkZphccH4+E+4wjnioujSn0bZjI92iDnG7K+mElIfDgRxmKWjG9WBNEgfkXFu6u1y5VVxMn7w9HlWZ2wfNXBo/T4PU4RGGeGGddOIIEwWPi1GGAWddhOCZOFSo2e1GzLsKQW4UBTZ2RaL6WZCaFFJJ+bNwhYXeJpRRwJw=="
Dec 09 17:38:27 volumio volumio[3539]: info: Loading plugin "upnp_browser"...
Dec 09 17:38:27 volumio go-librespot[3617]: time="2025-12-09T17:38:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:28 volumio go-librespot[3617]: time="2025-12-09T17:38:28-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:28 volumio go-librespot[3617]: time="2025-12-09T17:38:28-06:00" level=debug msg="completed challenge"
Dec 09 17:38:28 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:28] [connect] Successful connection
Dec 09 17:38:28 volumio go-librespot[3617]: time="2025-12-09T17:38:28-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 09 17:38:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "alarm-clock"...
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "airplay_emulation"...
Dec 09 17:38:29 volumio volumio[3539]: info: Starting Shairport Sync
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "last_100"...
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "webradio"...
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "i2s_dacs"...
Dec 09 17:38:29 volumio volumio[3539]: info: I2S DAC not set, start Auto-detection
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "volumiodiscovery"...
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** For more information see 
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** For more information see 
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 17:38:29 volumio volumio[3539]: *** WARNING *** For more information see 
Dec 09 17:38:29 volumio node[3539]: *** WARNING *** For more information see 
Dec 09 17:38:29 volumio volumio[3539]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 09 17:38:29 volumio volumio[3539]: info: Discovery: Started advertising with name: Volumio
Dec 09 17:38:29 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 17:38:29 volumio volumio[3539]: info: Loading plugin "bandcamp"...
Dec 09 17:38:31 volumio volumio[3539]: info: Plugin calmradio is not enabled
Dec 09 17:38:31 volumio volumio[3539]: info: Loading plugin "soundcloud"...
Dec 09 17:38:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36.
Dec 09 17:38:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:31 volumio go-librespot[3626]: go-librespot daemon starting...
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="app state loaded"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:31 volumio volumio[3539]: info: Loading plugin "spop"...
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-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 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-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 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=info msg="zeroconf server listening on port 40401"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="obtained new client token: AABNsFimOWHwMVNTprg2Tx54c3bQDUcLv+AXouV9PcjudVOesN7RHeNNx0Wl9RpGil8yBdQZmIPNh4dops6A8dX6LqoEyFMvCnyHcZXwtW2rcqQUogzihocW9dqEh1NV8LVWujPL55CXyIE8NSwebt/F3lBk7ijVt7PLMHWAFG68vF8nnRN1GYela1EeqWqakwFDiwzeyaYsCJ/fb3u750mfB2RaaDxfXfXAOESLXr6s05B6Upx05Csxzg=="
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38:31-06:00" level=debug msg="completed challenge"
Dec 09 17:38:31 volumio go-librespot[3627]: time="2025-12-09T17:38: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 09 17:38:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:32 volumio volumio[3539]: info: Loading plugin "squeezelite_mc"...
Dec 09 17:38:33 volumio volumio[3539]: info: Loading plugin "youtube2"...
Dec 09 17:38:33 volumio volumio[3539]: info: Loading plugin "ytcr"...
Dec 09 17:38:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37.
Dec 09 17:38:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:35 volumio go-librespot[3638]: go-librespot daemon starting...
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="app state loaded"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "ytmusic"...
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-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 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-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 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=info msg="zeroconf server listening on port 45045"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="obtained new client token: AAAtjz0Dk7mCciyeRvnj2g7M7ZseNaozEzlhwKM1JZ6LsF0CAX4wwA3FAXvUwle9WCgBQcmo7wOK4aMpP6dSQgT7LCqHBLLC2QDIgGFBoLCDtcXWnddKJo5ni8nBiOU3UXfFwJK1hmSDE+RXLpUWsZQsROCjr3xVRnS9+4q5HxMrZPX9AWl6E3pBUgfch4UuParJiY27pXI1HLxq/QWEtK3uVS3ZYYPr9uZJNRdVNb3uhxPDro8PZctxkA=="
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38:35-06:00" level=debug msg="completed challenge"
Dec 09 17:38:35 volumio go-librespot[3639]: time="2025-12-09T17:38: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 09 17:38:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin now_playing is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "outputs"...
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "albumart"...
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin example_plugin is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "inputs"...
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "updater_comm"...
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin mpdemulation is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "rest_api"...
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "websocket"...
Dec 09 17:38:35 volumio volumio[3539]: info: Starting Socket.io Server version 1.7.4
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin fusiondsp is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin mpdoutput is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Plugin RoonBridge is not enabled
Dec 09 17:38:35 volumio volumio[3539]: info: Loading plugin "podcast"...
Dec 09 17:38:36 volumio volumio[3539]: info: ControllerPodcast::constructor
Dec 09 17:38:36 volumio volumio[3539]: info: Loading plugin "volusonic"...
Dec 09 17:38:36 volumio volumio[3646]: Forking 3 albumart workers
Dec 09 17:38:37 volumio volumio[3539]: info: Applying required configuration parameters for plugin volusonic
Dec 09 17:38:37 volumio volumio[3539]: info: Loading plugin "backup_restore"...
Dec 09 17:38:37 volumio volumio[3658]: Starting albumart workers
Dec 09 17:38:37 volumio volumio[3657]: Starting albumart workers
Dec 09 17:38:37 volumio volumio[3656]: Starting albumart workers
Dec 09 17:38:38 volumio volumio[3539]: info: Applying required configuration parameters for plugin backup_restore
Dec 09 17:38:38 volumio volumio[3539]: info: Plugin rpi_eeprom_config is not enabled
Dec 09 17:38:38 volumio volumio[3539]: info: Plugin rpi_eeprom_updater is not enabled
Dec 09 17:38:38 volumio volumio[3539]: info: Loading plugin "scheduledrestart"...
Dec 09 17:38:38 volumio volumio[3539]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 09 17:38:38 volumio volumio[3539]: info: Plugin Bluetoothremote is not enabled
Dec 09 17:38:38 volumio volumio[3539]: info: Plugin music_services_shield is not enabled
Dec 09 17:38:38 volumio volumio[3539]: info: Loading plugin "Systeminfo"...
Dec 09 17:38:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38.
Dec 09 17:38:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:38 volumio go-librespot[3712]: go-librespot daemon starting...
Dec 09 17:38:38 volumio volumio[3539]: info: Plugin peppymeterbasic is not enabled
Dec 09 17:38:38 volumio volumio[3539]: info: Loading plugin "peppyspectrum"...
Dec 09 17:38:38 volumio go-librespot[3714]: time="2025-12-09T17:38:38-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:38 volumio go-librespot[3714]: time="2025-12-09T17:38:38-06:00" level=debug msg="app state loaded"
Dec 09 17:38:38 volumio go-librespot[3714]: time="2025-12-09T17:38:38-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:38 volumio go-librespot[3714]: time="2025-12-09T17:38:38-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-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 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-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 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=info msg="zeroconf server listening on port 38709"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=debug msg="obtained new client token: AAA0eJzG2G9skfMfnlJUCdmjEVCrannxOWRBVEkAbh95Is27XiVGSDgYqmUW5AXI+ZAgpEg0hx8AFQl4vUs9vPSVsJycWybog5lFRch5QrH8FcXvZJSCpQvNyuiZ123O+1OzX7qBkHCknl4YjOWhs13LEIKSxs4/UUmgUAQjzVa78GEYkqePrhv+T6yT3PLc3M0QAI59dmO4kcbIRdrn8vM7d/IdlC9wFqkNcqAJejOgJYe3vdCMsb0="
Dec 09 17:38:39 volumio volumio[3539]: info: Loading i18n strings for locale en
Dec 09 17:38:39 volumio volumio[3539]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 17:38:39 volumio volumio[3539]: Updating browse sources language
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38:39-06:00" level=debug msg="completed challenge"
Dec 09 17:38:39 volumio go-librespot[3714]: time="2025-12-09T17:38: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 09 17:38:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::initPlayerControls
Dec 09 17:38:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: Express server listening on port 3000
Dec 09 17:38:39 volumio volumio[3539]:  [Metrics]  WebUI:  14s 661.75ms 
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::resetVolumioState
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::getcurrentVolume
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:39 volumio sudo[3732]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 17:38:39 volumio sudo[3732]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio sudo[3732]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:39 volumio sudo[3734]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 17:38:39 volumio sudo[3734]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio sudo[3734]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:39 volumio volumio[3539]: info: Volumio Network Manager: Network status updated: 1
Dec 09 17:38:39 volumio volumio[3539]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::pushState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::updateTrackBlock
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrackBlock
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:39 volumio volumio[3539]: info: Reloading queue from file
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::setRepeat null single undefined
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::pushState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::setRandom null
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::pushState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:39 volumio volumio[3539]: info: Setting Device type: Raspberry PI
Dec 09 17:38:39 volumio volumio[3539]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:39 volumio volumio[3539]: info: CoreStateMachine::pushState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:39 volumio sudo[3747]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 17:38:39 volumio sudo[3747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio volumio[3539]: info: Completed loading Core Plugins
Dec 09 17:38:39 volumio volumio[3539]: info: Preparing to generate the ALSA configuration file
Dec 09 17:38:39 volumio volumio[3539]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 17:38:39 volumio volumio[3539]: info: Discovery: Found device Volumio
Dec 09 17:38:39 volumio sudo[3747]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 17:38:39 volumio volumio[3539]: info: Discovery: Found device Volumio
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:39 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:39 volumio volumio[3539]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 17:38:39 volumio volumio[3539]: info: Reading ALSA contributions from plugins.
Dec 09 17:38:39 volumio volumio[3539]: info: Upmpdcli Daemon Started
Dec 09 17:38:39 volumio volumio[3539]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 17:38:39 volumio volumio[3539]: info: Output device has changed, restarting MPD
Dec 09 17:38:39 volumio volumio[3539]: info: Output device has changed, restarting Shairport Sync
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:39 volumio sudo[3751]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:39 volumio sudo[3751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio sudo[3751]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:39 volumio sudo[3753]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:39 volumio sudo[3753]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio volumio[3539]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:39 volumio volumio[3539]: info: ___________ START PLUGINS ___________
Dec 09 17:38:39 volumio volumio[3539]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 17:38:39 volumio volumio[3539]: info: Creating MPD Configuration file
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:39 volumio volumio[3539]: info: [1765323519910] CoreMusicLibrary::Adding element Media Servers
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:39 volumio sudo[3761]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:39 volumio sudo[3761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio sudo[3763]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:39 volumio sudo[3763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:39 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 17:38:39 volumio sudo[3761]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:39 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:40 volumio volumio[3539]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520035] CoreMusicLibrary::Adding element Last_100
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520041] CoreMusicLibrary::Adding element Webradio
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 17:38:40 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 17:38:40 volumio systemd[1]: mpd.service: Consumed 4.505s CPU time.
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:38:40 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 17:38:40 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:40 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 17:38:40 volumio volumio[3539]: info: Initializing BBC Radios
Dec 09 17:38:40 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:40 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520124] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520138] CoreMusicLibrary::Adding element SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: info: Creating Spotify config file
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:40 volumio sudo[3788]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 17:38:40 volumio sudo[3788]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 17:38:40 volumio sudo[3788]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:40 volumio volumio[3539]: info: [squeezelite_mc] Starting proxy server...
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520502] CoreMusicLibrary::Adding element YouTube2
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520520] CoreMusicLibrary::Adding element YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520532] CoreMusicLibrary::Adding element Podcast
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Podcast
Dec 09 17:38:40 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:40] [connect] Successful connection
Dec 09 17:38:40 volumio volumio[3539]: info: Loading i18n strings for locale en
Dec 09 17:38:40 volumio volumio[3539]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 17:38:40 volumio volumio[3539]: Updating browse sources language
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Podcast
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Podcast
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:40 volumio volumio[3539]: info: [1765323520591] CoreMusicLibrary::Adding element Volusonic
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Podcast
Dec 09 17:38:40 volumio volumio[3539]: Cannot find translation for source Volusonic
Dec 09 17:38:40 volumio volumio[3539]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 17:38:40 volumio volumio[3539]: info: Volumio Calling Home
Dec 09 17:38:40 volumio volumio[3539]: info: [squeezelite_mc] Proxy server started on port 34539
Dec 09 17:38:40 volumio volumio[3539]: info: Preparing to generate the ALSA configuration file
Dec 09 17:38:40 volumio volumio[3539]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 17:38:40 volumio volumio[3539]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 17:38:40 volumio volumio[3539]: info: Reading ALSA contributions from plugins.
Dec 09 17:38:40 volumio volumio[3539]: info: MPD Permissions set
Dec 09 17:38:40 volumio volumio[3539]: info: MPD Permissions set
Dec 09 17:38:40 volumio volumio-remote-updater[9752]: [2025-12-09 17:38:40] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765323520 101
Dec 09 17:38:40 volumio volumio[3539]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1
Dec 09 17:38:40 volumio volumio[3539]: info: Spotify config file written
Dec 09 17:38:40 volumio sudo[3798]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 17:38:40 volumio sudo[3798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:41 volumio volumio[3539]: 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 09 17:38:41 volumio volumio[3539]: info: VolumeController:: Volume=86 Mute =false
Dec 09 17:38:41 volumio volumio[3539]: info: CoreStateMachine::pushState
Dec 09 17:38:41 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::volumioPushState
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Server discovery started
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Player finder started
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio go-librespot[3800]: go-librespot daemon starting...
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio sudo[3798]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="app state loaded"
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: No need to fix Spotify hosts
Dec 09 17:38:41 volumio volumio[3539]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3
Dec 09 17:38:41 volumio volumio[3539]: info: Volumio called home
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-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 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-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 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-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 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=info msg="zeroconf server listening on port 44015"
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 17:38:41 volumio volumio[3539]: 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 09 17:38:41 volumio volumio[3539]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 17:38:41 volumio volumio[3539]: SPOTIFY: BQDFE0R0B9fxkn1phfcGk_AyJXj9A_qLvJlYNCUwMAZdIhov_Malhw2B3kMD1yQEM35-sYSQqru6LpTjwT1clMzrbDfH754--CRlGPpMI5OCVrUSo2pj9i52w_poxElmv6yzHSGRX4oCtqByV13Cl-me8e4_qYqCh5-G04BlglkUEXQi87xDSM4C1sOY3IaZH9uY1wLuJts4VHcKJWF8UFrgbrdmLwyzNl9YpIo
Dec 09 17:38:41 volumio volumio[3539]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 17:38:41 volumio volumio[3539]: info: New Spotify access token = BQDFE0R0B9fxkn1phfcGk_AyJXj9A_qLvJlYNCUwMAZdIhov_Malhw2B3kMD1yQEM35-sYSQqru6LpTjwT1clMzrbDfH754--CRlGPpMI5OCVrUSo2pj9i52w_poxElmv6yzHSGRX4oCtqByV13Cl-me8e4_qYqCh5-G04BlglkUEXQi87xDSM4C1sOY3IaZH9uY1wLuJts4VHcKJWF8UFrgbrdmLwyzNl9YpIo
Dec 09 17:38:41 volumio volumio[3539]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 17:38:41 volumio volumio[3539]: info: Starting Shairport Sync
Dec 09 17:38:41 volumio volumio[3539]: info: Starting Shairport Sync
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="obtained new client token: AACG+XKZaowqsCBmviMNzgHGKRKYo3SXDAiqUWxCV9TnOujwnwMxv2CT2LmLserv7uiKCYsEl8+AerztobgbYhV7nJwiyB5QunC5BJDwiqumrSny2IBpNM6GpklMy081u4yoEq49tmTq/WfsK77F3DRIPh8v1PZDS8yNPtv1MwazHMKt2kIawQaGLjtOEV19xZWyvkIU3IaMLYk8+TdcNcDbg8cGC+bGBdEBGOcy3FkfBDgJHIaG+M+HGw=="
Dec 09 17:38:41 volumio volumio[3539]: info: Starting Shairport Sync
Dec 09 17:38:41 volumio sudo[3826]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:41 volumio sudo[3826]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio sudo[3828]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:41 volumio sudo[3828]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:41 volumio sudo[3830]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:41 volumio sudo[3823]:  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 09 17:38:41 volumio sudo[3830]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio sudo[3823]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 17:38:41 volumio sudo[3823]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=debug msg="completed challenge"
Dec 09 17:38:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:41 volumio systemd[1]: shairport-sync.service: Consumed 1.927s CPU time.
Dec 09 17:38:41 volumio volumio[3539]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 17:38:41 volumio volumio[3539]: info: Output device has changed, restarting MPD
Dec 09 17:38:41 volumio volumio[3539]: info: Output device has changed, restarting Shairport Sync
Dec 09 17:38:41 volumio go-librespot[3808]: time="2025-12-09T17:38:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:41 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:41 volumio sudo[3836]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 17:38:41 volumio sudo[3836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio sudo[3836]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio sudo[3839]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 17:38:41 volumio sudo[3839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:41 volumio volumio[3539]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 17:38:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:41 volumio sudo[3826]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio sudo[3828]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio sudo[3830]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:41 volumio volumio[3539]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 17:38:41 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 17:38:41 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 17:38:41 volumio systemd[1]: mpd.service: Consumed 1.680s CPU time.
Dec 09 17:38:41 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 17:38:41 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:41 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 17:38:41 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 17:38:42 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 17:38:42 volumio sudo[3866]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 17:38:42 volumio sudo[3866]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:42 volumio sudo[3866]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:42 volumio volumio[3539]: info: MPD Permissions set
Dec 09 17:38:42 volumio volumio[3539]: info: Shairport-Sync Started
Dec 09 17:38:42 volumio volumio[3539]: Error adding Membership: Error: addMembership EINVAL
Dec 09 17:38:42 volumio volumio[3539]: info: Shairport-Sync Started
Dec 09 17:38:42 volumio volumio[3539]: info: Shairport-Sync Started
Dec 09 17:38:42 volumio volumio[3539]: 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 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:42 volumio sudo[3867]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 17:38:42 volumio sudo[3867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 17:38:42 volumio sudo[3867]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:42 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:42 volumio volumio[3539]: 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 09 17:38:42 volumio volumio[3539]: info: Spotify Successfully logged in
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 17:38:42 volumio volumio[3539]: info: [1765323522325] CoreMusicLibrary::Adding element Spotify
Dec 09 17:38:42 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source Bandcamp Discover
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source SoundCloud
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source YouTube2
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source YouTube Music
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source Podcast
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source Volusonic
Dec 09 17:38:42 volumio volumio[3539]: Cannot find translation for source Spotify
Dec 09 17:38:42 volumio sudo[3872]:  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 09 17:38:42 volumio sudo[3872]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:42 volumio sudo[3872]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:42 volumio volumio[3539]: info: Starting Shairport Sync
Dec 09 17:38:42 volumio sudo[3882]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 17:38:42 volumio sudo[3882]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:42 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 09 17:38:42 volumio sudo[3885]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 17:38:42 volumio sudo[3885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:42 volumio systemd[1]: Reloading.
Dec 09 17:38:42 volumio volumio[3539]: info: [squeezelite_mc] Notification listener started
Dec 09 17:38:42 volumio volumio[3539]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 17:38:43 volumio volumio[3539]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 17:38:43 volumio volumio[3539]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 17:38:43 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:43 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:43 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:38:43 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 17:38:44 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:38:44 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:38:44 volumio volumio[3539]: info: go-librespot daemon successfully initialized
Dec 09 17:38:44 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:44 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:44 volumio sudo[3885]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:44 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:44 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 17:38:44 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 17:38:44 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:44 volumio systemd[1]: shairport-sync.service: Consumed 1.563s CPU time.
Dec 09 17:38:44 volumio sudo[3905]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:44 volumio sudo[3905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:44 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 17:38:44 volumio sudo[3882]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39.
Dec 09 17:38:44 volumio volumio[3539]: info: Shairport-Sync Started
Dec 09 17:38:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:44 volumio go-librespot[3908]: go-librespot daemon starting...
Dec 09 17:38:44 volumio go-librespot[3909]: time="2025-12-09T17:38:44-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:44 volumio go-librespot[3909]: time="2025-12-09T17:38:44-06:00" level=debug msg="app state loaded"
Dec 09 17:38:44 volumio go-librespot[3909]: time="2025-12-09T17:38:44-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:44 volumio go-librespot[3909]: time="2025-12-09T17:38:44-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:44 volumio sudo[3905]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:44 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 17:38:44 volumio sudo[3930]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 17:38:44 volumio sudo[3930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:45 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 17:38:45 volumio volumio[3539]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 17:38:45 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:45 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=info msg="zeroconf server listening on port 39017"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="obtained new client token: AACT/oxsmkua10wdFB9AvJYBQgi9L1VsRcIZ/pmh+L+cZKWNr/ikSBjsGejoscEwYLhhmduTipe607E3rJattRQnSb/mHmIAAoL41JpkDckg9KiJhuH2F0N4K6Bkihd4HHYMD66XwqLu/StUsTJrVj9BtgvXPtZdEK83ND0sDkO4KfQQKvACNykkL94GUOeFQrSGkDHV7fG7lkWrblvgaiQ1Obaq0A7oJ+vWuTCmNZAudAViHkCEnaZqTQ=="
Dec 09 17:38:45 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 17:38:45 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 17:38:45 volumio sudo[3930]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-06:00" level=debug msg="completed challenge"
Dec 09 17:38:45 volumio go-librespot[3909]: time="2025-12-09T17:38:45-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 09 17:38:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:45 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:45 volumio sudo[3934]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:45 volumio sudo[3934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:45 volumio sudo[3934]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 17:38:46 volumio sudo[3938]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 17:38:46 volumio sudo[3938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:46 volumio sudo[3938]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 17:38:46 volumio sudo[3941]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 17:38:46 volumio sudo[3941]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:46 volumio mpd[3879]: 2025-12-09T17:38:46 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 17:38:46 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 17:38:46 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 17:38:46 volumio sudo[3941]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 17:38:46 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 17:38:46 volumio sudo[3763]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio sudo[3753]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio sudo[3839]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:46 volumio volumio[3539]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 17:38:46 volumio volumio[3539]:   assert.ok(self.idling)
Dec 09 17:38:46 volumio volumio[3539]: error: The expression evaluated to a falsy value:
Dec 09 17:38:46 volumio volumio[3539]:   assert.ok(self.idling)
Dec 09 17:38:46 volumio volumio[3539]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 17:38:46 volumio volumio[3539]:   assert.ok(self.idling)
Dec 09 17:38:46 volumio volumio[3539]: error: The expression evaluated to a falsy value:
Dec 09 17:38:46 volumio volumio[3539]:   assert.ok(self.idling)
Dec 09 17:38:46 volumio volumio[3539]: info: MPD running with PID3879
Dec 09 17:38:46 volumio volumio[3539]:  ,establishing connection
Dec 09 17:38:46 volumio volumio[3539]: error: updateQueue error: null
Dec 09 17:38:46 volumio volumio[3539]: error: updateQueue error: null
Dec 09 17:38:46 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:46 volumio sudo[3952]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:46 volumio sudo[3952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:46 volumio sudo[3952]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:47 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:47 volumio sudo[3955]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:47 volumio sudo[3955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:47 volumio sudo[3955]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:47 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:38:47 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:38:47 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:47 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:47 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:47 volumio sudo[3972]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:47 volumio sudo[3972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:48 volumio sudo[3972]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:48 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:48 volumio sudo[3975]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:48 volumio sudo[3975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40.
Dec 09 17:38:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:48 volumio go-librespot[3977]: go-librespot daemon starting...
Dec 09 17:38:48 volumio sudo[3975]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=debug msg="app state loaded"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-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 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-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 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=info msg="zeroconf server listening on port 45959"
Dec 09 17:38:48 volumio go-librespot[3978]: time="2025-12-09T17:38:48-06:00" level=debug msg="obtained new client token: AAC3UzJ9fwLkfnbYh8X61hRTwT6FcH7f8Jg+GH8qfaXovK5fFNIFSR+L6DUe5PS4NANIPmSUbYuE3n/JsZ/2NuPU0CmJcXLwCc7xt3AtQgEjSw+vR8be1lsF3cuB23vftCIwIAqB1fuuEbIYj8zayJRavlpPQcvBlmuZFv1f2Umysqf6xRuBr29z5Hauai5k4FcROwDanc6QkkKiPfFQyZtOPe/4V4W0ft9IOsLf40nc0cbsWR74dPVLJw=="
Dec 09 17:38:49 volumio go-librespot[3978]: time="2025-12-09T17:38:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:49 volumio go-librespot[3978]: time="2025-12-09T17:38:49-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:49 volumio go-librespot[3978]: time="2025-12-09T17:38:49-06:00" level=debug msg="completed challenge"
Dec 09 17:38:49 volumio go-librespot[3978]: time="2025-12-09T17:38: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 09 17:38:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:49 volumio volumio[3539]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 17:38:49 volumio sudo[3986]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 17:38:49 volumio sudo[3986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:49 volumio sudo[3986]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:49 volumio volumio[3539]: info: Completed starting Core Plugins
Dec 09 17:38:49 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:49 volumio volumio[3539]: info: -----    MyVolumio plugins startup     ----
Dec 09 17:38:49 volumio volumio[3539]: info: -------------------------------------------
Dec 09 17:38:49 volumio volumio[3539]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 17:38:49 volumio sudo[3989]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:49 volumio sudo[3989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:49 volumio sudo[3991]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:49 volumio sudo[3991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:49 volumio sudo[3994]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 17:38:49 volumio sudo[3994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:49 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 17:38:49 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 17:38:49 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 17:38:49 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 17:38:49 volumio sudo[3994]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:49 volumio mpd_monitor.sh[3997]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 17:38:49 volumio sudo[3989]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:49 volumio volumio[3539]: info: Successfully started MPD Monitor
Dec 09 17:38:49 volumio sudo[3991]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:49 volumio volumio[3539]: info: Successfully started MPD Monitor
Dec 09 17:38:49 volumio volumio[3539]: info: Successfully started MPD Monitor
Dec 09 17:38:50 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:50 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41.
Dec 09 17:38:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:52 volumio go-librespot[4001]: go-librespot daemon starting...
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="app state loaded"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-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 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-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 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-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 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=info msg="zeroconf server listening on port 44195"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="obtained new client token: AACnRRfGFOlOQ//GGCrUNgjS4w0X8sQYcFfqJcEdKiCUKM+mbREMzqrOQQeMFdr874fbwqZNRW3iOavJKpJ5cOmV+jHyGK4LiS20oglfVU9B2/IueQk9PzYwAgk9KAolrq3RurAFqfvYuOf74fQmkTYxG7RW6jF8EvwnrqPlyLKwBI4+uI5jrv/Sgksw28YZTLbsS5uogstCcBWR2bRo2u/9s0pHnPzSBLGSwLH0a6EQnlV0hN1yB5qMMw=="
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-06:00" level=debug msg="completed challenge"
Dec 09 17:38:52 volumio go-librespot[4002]: time="2025-12-09T17:38:52-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 09 17:38:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:54 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:54 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42.
Dec 09 17:38:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:56 volumio go-librespot[4009]: go-librespot daemon starting...
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="app state loaded"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-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 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-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 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-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 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=info msg="zeroconf server listening on port 42929"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="obtained new client token: AACzeaFnhJTTAKf1QZFKZa82B0aGHUxNiOqd3VsTzRadboDfoGLwIwmFothkRqg8LZd30ktu/OneqTpmiotffWjMMX5jPftKgvfFSr9VRDc2MChjGGDckdU0NJ+LSd45TVPiV98n+3lRRsQ/wd/67sMRPn6DlQH0RwV7AZK+Pb21FmVkEJK+nI0xFDOTYTtsKi/1z3EFL6dtUua06R2tAvTACxc0AJYjhz0hBIBW1bjslzYYLGa99pvOZw=="
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="completed keyexchange"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-06:00" level=debug msg="completed challenge"
Dec 09 17:38:56 volumio go-librespot[4010]: time="2025-12-09T17:38:56-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 09 17:38:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:38:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:38:57 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:38:57 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 17:38:57 volumio volumio[3539]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 17:38:58 volumio volumio[3539]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 17:38:58 volumio volumio[3539]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 17:38:58 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:58 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:38:58 volumio volumio[3539]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 17:38:58 volumio volumio[3539]: info: MyVolumio login type: Token
Dec 09 17:38:58 volumio volumio[3539]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 17:38:58 volumio volumio[3539]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 17:38:59 volumio volumio[3539]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 17:38:59 volumio volumio[3539]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 17:38:59 volumio volumio[3539]: info: Streaming services startup
Dec 09 17:38:59 volumio volumio[3539]: info: Starting Streaming Daemon
Dec 09 17:38:59 volumio sudo[4033]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 17:38:59 volumio sudo[4033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:38:59 volumio volumio[3539]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 17:38:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43.
Dec 09 17:38:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:38:59 volumio go-librespot[4039]: go-librespot daemon starting...
Dec 09 17:38:59 volumio sudo[4033]: pam_unix(sudo:session): session closed for user root
Dec 09 17:38:59 volumio volumio[3539]: error: Cannot start Volumio Streaming Daemon
Dec 09 17:38:59 volumio volumio[3539]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 17:38:59 volumio volumio[3539]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-06:00" level=debug msg="app state loaded"
Dec 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-06:00" level=debug msg="stored credentials not found"
Dec 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-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 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-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 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-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 09 17:38:59 volumio go-librespot[4040]: time="2025-12-09T17:38:59-06:00" level=info msg="zeroconf server listening on port 41601"
Dec 09 17:39:00 volumio volumio[3539]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 09 17:39:00 volumio go-librespot[4040]: time="2025-12-09T17:39:00-06:00" level=debug msg="obtained new client token: AADt4zq69Ccf4hSDrKLxo5DKYXYkmZegJOk8LrNn53MxeB6hJ6JID3xpPwHs4tQjWQtDGDDUrGZYpiIec6An29xZ+WpfMCHSul6+Z2dK5X7AZjQ5iItWQMV7dVetKFLJroaca8FTfXql4mI6dxK0PvQCL/EKwixis78hYQvxwbM5laS2kGK4R+E70+eH5Enu8Sxwtm6rRo8bst1mfNXab9Iq55irkufhl+Hpx6JuK0pDiTsWBw/UPkU="
Dec 09 17:39:00 volumio go-librespot[4040]: time="2025-12-09T17:39:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:00 volumio go-librespot[4040]: time="2025-12-09T17:39:00-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:00 volumio go-librespot[4040]: time="2025-12-09T17:39:00-06:00" level=debug msg="completed challenge"
Dec 09 17:39:00 volumio go-librespot[4040]: time="2025-12-09T17:39:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:39:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:00 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:00 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:00 volumio volumio[3539]: info: MyVolumio token set successfully
Dec 09 17:39:00 volumio volumio[3539]: info: MYVOLUMIO: Adding device
Dec 09 17:39:00 volumio volumio[3539]: info: MYVOLUMIO: Evaluating Server
Dec 09 17:39:00 volumio volumio[3539]: info: MyVolumio status changed
Dec 09 17:39:00 volumio volumio[3539]: info: Streaming services startup
Dec 09 17:39:00 volumio volumio[3539]: info: Starting Streaming Daemon
Dec 09 17:39:00 volumio volumio[3539]: info: Removing browser output: myVolumio user plan is not superstar
Dec 09 17:39:00 volumio volumio[3539]: info: Removing audio output:
Dec 09 17:39:00 volumio volumio[3539]: info: Stoppping Tunnel 1
Dec 09 17:39:00 volumio sudo[4068]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 17:39:00 volumio sudo[4068]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:39:00 volumio sudo[4070]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 09 17:39:00 volumio sudo[4070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio sudo[4068]: pam_unix(sudo:session): session closed for user root
Dec 09 17:39:00 volumio volumio[3539]: error: Cannot start Volumio Streaming Daemon
Dec 09 17:39:00 volumio volumio[3539]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 17:39:00 volumio volumio[3539]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 17:39:00 volumio sudo[4070]: pam_unix(sudo:session): session closed for user root
Dec 09 17:39:00 volumio volumio[3539]: info: Remote SSH Stopped
Dec 09 17:39:00 volumio volumio[3539]: info: Setting Geolocation for MyVolumio to us4
Dec 09 17:39:00 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:00 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:00 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:01 volumio volumio[3539]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 17:39:01 volumio volumio[3539]: info: Updating MyVolumio device info
Dec 09 17:39:01 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:01 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:01 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:02 volumio volumio[3539]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 17:39:03 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:03 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44.
Dec 09 17:39:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:03 volumio go-librespot[4073]: go-librespot daemon starting...
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="app state loaded"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=info msg="zeroconf server listening on port 43721"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="obtained new client token: AAAd2tptQwhEJEYclU2eXZwdPx9Qn55LJUa1Tx/WBpNoojb6I9muASebkflO4Unbubj8N4Lj+qee5rPYvbXBcf4stb9IT0mKXq476CI94SZFynEEPCb3FTEVDvr4xbsyojE4RJP8NyvWpcwtFEtpVfP5g9+8rT3/xLAl7AXbBC0W8kd3dDZ75l49XmgDUwO/yoMs9CctN3j0bar5sxXw5ogNXNaX5ttlS+uT+Cf2VX76t/YpTQK0PD9yYw=="
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39:03-06:00" level=debug msg="completed challenge"
Dec 09 17:39:03 volumio go-librespot[4074]: time="2025-12-09T17:39: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 09 17:39:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:05 volumio volumio[3539]: info: MYVOLUMIO: Adding device
Dec 09 17:39:05 volumio volumio[3539]: info: MYVOLUMIO: Evaluating Server
Dec 09 17:39:05 volumio volumio[3539]: info: Setting Geolocation for MyVolumio to us1
Dec 09 17:39:05 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:05 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:05 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:05 volumio volumio[3539]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 17:39:06 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:06 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:06 volumio volumio[3539]: info: Updating MyVolumio device info
Dec 09 17:39:06 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:06 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:06 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:06 volumio volumio[3539]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 17:39:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45.
Dec 09 17:39:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:07 volumio go-librespot[4099]: go-librespot daemon starting...
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="app state loaded"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-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 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-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 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=info msg="zeroconf server listening on port 41829"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="obtained new client token: AADWMRcjc7rm9BlrZtqe3q18UFcGPFNHInmgz1udIiL3t3N4S9bdQip32NICVmCtgObGQBayZ+fmI+EEBb36w0WhYES/6Sz6CZ+pgAtZIw9TXNX+ahdcwl3Ku02B/6iThjI6aD4Ezo+qQ6bbfaxpT8aHL/ZBN+RJJhMJp/6xvas6QSzK/X2u3vgAcITGMSBVaVFsTFVGJuYDVuhEa45pUUsppxqIhiU1qIJk3DFg+deFhBbG/wOVkG1FYA=="
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39:07-06:00" level=debug msg="completed challenge"
Dec 09 17:39:07 volumio go-librespot[4100]: time="2025-12-09T17:39: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 09 17:39:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:09 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:09 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:10 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:39:10 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:10 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 09 17:39:10 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 09 17:39:10 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 09 17:39:10 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 09 17:39:10 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 09 17:39:10 volumio volumio[3539]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\nProduction line
\n
\nFIX
\n\nNodejs 20.5.1 version pinning with static package fallback
\n\n","title":"Update v4.073","updateavailable":true}
Dec 09 17:39:10 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 09 17:39:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46.
Dec 09 17:39:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:11 volumio go-librespot[4128]: go-librespot daemon starting...
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="app state loaded"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-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 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-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 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=info msg="zeroconf server listening on port 43635"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="obtained new client token: AACWOqN6DocFC1sfpE+LDeLrPyUbJ/ZDszRk0r4Z3z913QDu2il0nkH+YW7cep8GfF/528p47LX70byuaAVLbzlcqcndHYHAseo73rtZZBygmGs3JmL2QL4VKGCLf0xVrA6Mq/Np0mH0LsfPEJ08Aj3LPc+idSCjQuY7bbp2faUzt/i4fUf86kC5FVYZjnubLeil1IOEqaJiKM6kac5Q/7BeUydoqNjSCuwR58x2MExsa7098tdwEMa+7A=="
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39:11-06:00" level=debug msg="completed challenge"
Dec 09 17:39:11 volumio go-librespot[4129]: time="2025-12-09T17:39: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 09 17:39:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:12 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:12 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:13 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 09 17:39:13 volumio volumio[3539]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4
Dec 09 17:39:13 volumio volumio[3539]: info: CoreCommandRouter::volumioGetState
Dec 09 17:39:13 volumio volumio[3539]: info: CorePlayQueue::getTrack 0
Dec 09 17:39:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47.
Dec 09 17:39:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:14 volumio go-librespot[4136]: go-librespot daemon starting...
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=debug msg="app state loaded"
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-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 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-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 09 17:39:14 volumio go-librespot[4137]: time="2025-12-09T17:39:14-06:00" level=info msg="zeroconf server listening on port 35883"
Dec 09 17:39:15 volumio go-librespot[4137]: time="2025-12-09T17:39:15-06:00" level=debug msg="obtained new client token: AAAzCi83whqnRuuh9/69dij9yef3VTUQDroh3Ayv51Z5DE50tm3uRYIxFfNOAKB53LNqLuNeBmL+5pnY/kzhrtkgto5m2AxJhOBPex6Y5rxpADve3+o4Z/DZ44z9O2ToQVgOe7EYfe9fw2hFCy4HkepJsgaTNlXIWSJDBhNrSep98Zi2jByTO7RsL4D4saw83aZIAnMlKGXGrC00fCbsOJAKuVD+7C0gXwEoE2WqJZxlIPEnVEp4rEA="
Dec 09 17:39:15 volumio go-librespot[4137]: time="2025-12-09T17:39:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:15 volumio go-librespot[4137]: time="2025-12-09T17:39:15-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:15 volumio go-librespot[4137]: time="2025-12-09T17:39:15-06:00" level=debug msg="completed challenge"
Dec 09 17:39:15 volumio go-librespot[4137]: time="2025-12-09T17:39: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 09 17:39:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:15 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:15 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:18 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:18 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48.
Dec 09 17:39:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:18 volumio go-librespot[4158]: go-librespot daemon starting...
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="app state loaded"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::volumioGetBrowseSources
Dec 09 17:39:18 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39: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 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39: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 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39: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 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=info msg="zeroconf server listening on port 39523"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="obtained new client token: AAArqKKRif34K7VXiFlcS0MVU+2sKrmpTkUZS8T7/W0RUd3E4kOYwyo4kScQnrmQB9TyEy44Zqm0jIm18I/OsI4Mo5KNgd5X8vZREj4Lull/Lla7OKRTzUiPf29jO4cob7l2R8ksqJwP8Dqp+FM96NNwGFrHrDg2/SdT0KydA1XyxhRI8JANpSLblQi/yfUqioG/OdR3OTgUjd2jttdwQZCM7KqH8uqNhQkXUezNPR/nL16EMoa+zvMouw=="
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-06:00" level=debug msg="completed challenge"
Dec 09 17:39:18 volumio go-librespot[4159]: time="2025-12-09T17:39:18-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 09 17:39:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:19 volumio volumio[3539]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Dec 09 17:39:19 volumio volumio[3539]: info: Completed starting MyVolumio Plugin
Dec 09 17:39:19 volumio volumio[3539]:  [Metrics]  CommandRouter:  54s 386.60ms 
Dec 09 17:39:19 volumio volumio[3539]: info: CoreCommandRouter::volumiosetStartupVolume
Dec 09 17:39:19 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 17:39:19 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 17:39:19 volumio volumio[3539]: info: CoreCommandRouter::Close All Modals sent
Dec 09 17:39:19 volumio volumio[3539]: info: CoreCommandRouter::Close All Modals sent
Dec 09 17:39:20 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Dec 09 17:39:20 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 09 17:39:20 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Dec 09 17:39:21 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:21 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49.
Dec 09 17:39:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:22 volumio go-librespot[4173]: go-librespot daemon starting...
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="app state loaded"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39: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 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39: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 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39: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 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=info msg="zeroconf server listening on port 43111"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="obtained new client token: AAATdyv9PEFbpdD0Cemwqt8ucxNJIJ0fuQcMJJPU/YkfzEh4+5wWIe4PpS+RDHAOs1dZ/gYRje+mphkW3jKZOU0hfsmnnwMF545uTYj/sV7HLccMoBdacE2DsPQ3mW8UpPO7hTzSGH4oo/nMc5Q3xDENqlQSGq8/hMn0BxhPnyzyF1Ut4KptndusblTjje6xGUm+ZrOhPeUHr0gFwktnRYrSg3o8NxjwHGk3WieNpnlr/ZPbZ2t26+tb/w=="
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=debug msg="completed challenge"
Dec 09 17:39:22 volumio go-librespot[4174]: time="2025-12-09T17:39:22-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:39:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:24 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:24 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50.
Dec 09 17:39:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:26 volumio go-librespot[4181]: go-librespot daemon starting...
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="app state loaded"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=info msg="zeroconf server listening on port 36401"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="obtained new client token: AABfw8wpu7klSvr7zOKdV7Oj/dFmmyht9DSluDDTeL2xpa+n9lQsQyYdeODuAhiBInbkwcAPXdy0vKlbVyciQhtPEtnN2xWKmjykPh/SaIkuQDmQWQ8n1fchYhpySfQLNxxkx2o6/jBh/Hw/VsrVuzjgtn9xliBxmwRZXiQxW2/Yhh1Cx8AEbhAx+/nExEHu+XqUigWm3BhAsCZ90UEHneQSZnoS/EUznC1Xq4lx6jkbqrPXGpDzplsbKA=="
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39:26-06:00" level=debug msg="completed challenge"
Dec 09 17:39:26 volumio go-librespot[4182]: time="2025-12-09T17:39: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 09 17:39:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:26 volumio volumio[3539]: info: BOOT COMPLETED
Dec 09 17:39:27 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:27 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51.
Dec 09 17:39:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:29 volumio go-librespot[4206]: go-librespot daemon starting...
Dec 09 17:39:29 volumio go-librespot[4207]: time="2025-12-09T17:39:29-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:29 volumio go-librespot[4207]: time="2025-12-09T17:39:29-06:00" level=debug msg="app state loaded"
Dec 09 17:39:29 volumio go-librespot[4207]: time="2025-12-09T17:39:29-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:29 volumio go-librespot[4207]: time="2025-12-09T17:39:29-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-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 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-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 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-06:00" level=info msg="zeroconf server listening on port 36467"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-06:00" level=debug msg="obtained new client token: AAAH8zHkYHkH7ArMLpx+tqQp9nBY1OSlfFiOOQc+xSbzJiFSjrRCaEcSlz2qigUYv6q+Zuvdaxm5SDQHK1kv1WXpAT1ikgVkEDP9zJwpyv4naPp+QQDAw7+26jDFILsy8SVYECyNOzSZWNIB8DURcwcW/y6/vTjeJu8WctUQQQAXdhWJUXuAmfQnBHREohU0VIm0U/iVfHL7F0B8+2EXdUKR+Ovl5uXiq9yd3H8wSInKV5KxnaCnuAw="
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39:30-06:00" level=debug msg="completed challenge"
Dec 09 17:39:30 volumio go-librespot[4207]: time="2025-12-09T17:39: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 09 17:39:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:30 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:30 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:33 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52.
Dec 09 17:39:33 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:33 volumio go-librespot[4214]: go-librespot daemon starting...
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="app state loaded"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-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 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-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 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-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 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=info msg="zeroconf server listening on port 41627"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="obtained new client token: AADUU5Cumfo2WhaTiFLwgvQ/UqEx/rDIWlZJL1f5s8Vl6ub2pJnqssrMOqe2mVZxwb99fd+w+ZrQLwkVspRmOZ6EfERz5q/TinU3DCBsKHRv5756H0duVSAdsmfUASzADiyjUCcmWEXiDMYHTQleS7VG8lD8pJXnIcaghRNpH7QnVkbzIqjTZ2EjcxwH3D2jqNUzgQq/Jrq8Hn9TE0n1kvk8gGsEZgXIb3Ke8ULpvInpbGYfZH60DfSLlg=="
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-06:00" level=debug msg="completed challenge"
Dec 09 17:39:33 volumio go-librespot[4215]: time="2025-12-09T17:39:33-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 09 17:39:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:36 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:36 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53.
Dec 09 17:39:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:37 volumio go-librespot[4222]: go-librespot daemon starting...
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="app state loaded"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=info msg="zeroconf server listening on port 42215"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="obtained new client token: AABbI6jSgWwnnnuFIqLofT2P9z6KrtUgrEyPoZiOOAOO63CrX0gtlOy1wk/Ll4GzP6SZ4LgnrgS14JC1/CXqU82BpH6McDC0XaKt86+qMQYVfXJ5LbJyaTJn/vvqnRhzoWUZorz498D/mHJONA59X3cVvFAUMbeV+Q1Q96PFdw2nZafCVaGvg6GlMwM9QBVKH8kd0yNBv/X7wh1blyQiFf8vNRsubQm0roY9CGOjGb4oS2bZOKu5fE6bsg=="
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=debug msg="completed challenge"
Dec 09 17:39:37 volumio go-librespot[4223]: time="2025-12-09T17:39:37-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:39:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:39 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:39 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:40 volumio volumio[3539]: info: UPDATER: Scheduling automatic update
Dec 09 17:39:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStartTime
Dec 09 17:39:40 volumio volumio[3539]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStopTime
Dec 09 17:39:40 volumio volumio[3539]: info: UPDATER: Auto update will take place at: Wed Dec 10 2025 04:49:06 GMT-0600 (Central Standard Time)
Dec 09 17:39:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54.
Dec 09 17:39:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:40 volumio go-librespot[4245]: go-librespot daemon starting...
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="app state loaded"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-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 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-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 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-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 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=info msg="zeroconf server listening on port 38791"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="obtained new client token: AACGTKWuETrgXmwbKyaTVQDxtEqKsGat31ihh8gi9XjNf5m54g6I1O7QXpqC3T7JbSqmw1Ho5KmHl6cOvMcuXt63KZDmsk06avRVxbJ5ioMfgV4wt5I9Nu/zqz+1OVzxai9j6bw9rDwy/CAkXwL8rfPN6kN32Ed+KcKv/PrUQrqZvKFUvNQx+xsoeMG9c6Vz9aecKm3Gsf704wk9kAj74ME8I0ENaaJOlVZno6ME433VxI8KPfvrc5jzTw=="
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=debug msg="completed challenge"
Dec 09 17:39:41 volumio go-librespot[4246]: time="2025-12-09T17:39:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 17:39:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:42 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:42 volumio volumio[3539]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55.
Dec 09 17:39:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:44 volumio go-librespot[4254]: go-librespot daemon starting...
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="app state loaded"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=info msg="zeroconf server listening on port 39155"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="obtained new client token: AABYbpot2Fx/e0k/umBXfSxCX1b6/oci7mPkWKRZDo2WbBp2fr+CQ2Qdt4+KI5CCfNHPb7Qkwzd6vO8LsL6p3yOMZcvWqjLcu7TRWn6EaxhN3cJ4Ia2AbEg4YvbeVFwVRycBjktllW9hWy+weyLPP6joFX985TgQVd+oeiZ6vD0anLbQklbr+0vX06tDQinXz+NXaH5mnnscePhhL27uIzjvi3xs3Alzi8U33unNkwd6VjYjxdj3HAqhvA=="
Dec 09 17:39:45 volumio volumio[3539]: info: Initializing connection to go-librespot Websocket
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="new websocket client"
Dec 09 17:39:45 volumio volumio[3539]: info: Connection to go-librespot Websocket established
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-06:00" level=debug msg="completed challenge"
Dec 09 17:39:45 volumio go-librespot[4255]: time="2025-12-09T17:39:45-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 09 17:39:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 17:39:45 volumio volumio[3539]: info: Connection to go-librespot Websocket closed
Dec 09 17:39:48 volumio volumio[3539]: info: Getting Spotify volume
Dec 09 17:39:48 volumio volumio[3539]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 17:39:48 volumio volumio[3539]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 17:39:48 volumio volumio[3539]:     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 09 17:39:48 volumio volumio[3539]:   errno: -111,
Dec 09 17:39:48 volumio volumio[3539]:   code: 'ECONNREFUSED',
Dec 09 17:39:48 volumio volumio[3539]:   syscall: 'connect',
Dec 09 17:39:48 volumio volumio[3539]:   address: '127.0.0.1',
Dec 09 17:39:48 volumio volumio[3539]:   port: 9879,
Dec 09 17:39:48 volumio volumio[3539]:   response: undefined
Dec 09 17:39:48 volumio volumio[3539]: }
Dec 09 17:39:48 volumio volumio[3539]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 17:39:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56.
Dec 09 17:39:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 17:39:48 volumio go-librespot[4288]: go-librespot daemon starting...
Dec 09 17:39:48 volumio go-librespot[4289]: time="2025-12-09T17:39:48-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 17:39:48 volumio go-librespot[4289]: time="2025-12-09T17:39:48-06:00" level=debug msg="app state loaded"
Dec 09 17:39:48 volumio go-librespot[4289]: time="2025-12-09T17:39:48-06:00" level=debug msg="stored credentials not found"
Dec 09 17:39:48 volumio go-librespot[4289]: time="2025-12-09T17:39:48-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-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 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-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 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=info msg="zeroconf server listening on port 42837"
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=debug msg="obtained new client token: AAAcBetUBRFgtRChP7dKoFJrEPdP4oc8Bw9JDTVYgKtcxQzxLeifRdAoMFM9uw0UnVtQus1ZcblaIO+VUolz6UI5wndcV6oveoiDc6HM1BB0mMpY4fNC9jcWxpfvVFHFQZLmAALujduNuN9vYZEuC1juMEiw1c2VTpXX6miPbxughvPugI/s81Nq+vGu/ILLbfJlB7tdIlokzLplcZdD+0yDhNCyoAtbEn/hpJz1AIMjyn/c4MGnDiw="
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 17:39:49 volumio sudo[4299]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 17:38'
Dec 09 17:39:49 volumio sudo[4299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=debug msg="completed keyexchange"
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39:49-06:00" level=debug msg="completed challenge"
Dec 09 17:39:49 volumio go-librespot[4289]: time="2025-12-09T17:39: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 09 17:39:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 17:39:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
VOLUMIO_BUILD_VERSION="ac7dd5922ede329d1459d48b226ddc71f5209a2c"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025"
VOLUMIO_VERSION="4.069"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"