Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="completed challenge" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:00 music volumio[20926]: info: Starting UPNP Browser Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "alarm-clock"... Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "airplay_emulation"... Feb 09 07:51:00 music volumio[20926]: info: Starting Shairport Sync Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "last_100"... Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "webradio"... Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "i2s_dacs"... Feb 09 07:51:00 music volumio[20926]: info: I2S DAC not set, start Auto-detection Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "volumiodiscovery"... Feb 09 07:51:00 music volumio[20926]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:00 music volumio[20926]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:00 music volumio[20926]: *** WARNING *** For more information see Feb 09 07:51:00 music volumio[20926]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:00 music volumio[20926]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:00 music volumio[20926]: *** WARNING *** For more information see Feb 09 07:51:00 music node[20926]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:00 music node[20926]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:00 music node[20926]: *** WARNING *** For more information see Feb 09 07:51:00 music node[20926]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:00 music node[20926]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:00 music node[20926]: *** WARNING *** For more information see Feb 09 07:51:00 music volumio[20926]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 09 07:51:00 music volumio[20926]: info: Discovery: Started advertising with name: music Feb 09 07:51:00 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:00 music volumio[20926]: info: Loading plugin "spop"... Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=debug msg="completed challenge" Feb 09 07:51:00 music go-librespot[20998]: time="2026-02-09T07:51:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:01 music go-librespot[20998]: time="2026-02-09T07:51:01-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.255.62:80: connect: connection refused" Feb 09 07:51:01 music go-librespot[20998]: time="2026-02-09T07:51:01-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:01 music go-librespot[20998]: time="2026-02-09T07:51:01-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:01 music go-librespot[20998]: time="2026-02-09T07:51:01-05:00" level=debug msg="completed challenge" Feb 09 07:51:01 music go-librespot[20998]: time="2026-02-09T07:51:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "outputs"... Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "albumart"... Feb 09 07:51:01 music volumio[20926]: info: Plugin example_plugin is not enabled Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "inputs"... Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "updater_comm"... Feb 09 07:51:01 music volumio[20926]: info: Plugin mpdemulation is not enabled Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "rest_api"... Feb 09 07:51:01 music volumio[20926]: info: Loading plugin "websocket"... Feb 09 07:51:01 music volumio[20926]: info: Starting Socket.io Server version 1.7.4 Feb 09 07:51:02 music volumio[20926]: info: Loading i18n strings for locale en Feb 09 07:51:02 music volumio[20926]: Updating browse sources language Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::initPlayerControls Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:02 music volumio[20926]: Express server listening on port 3000 Feb 09 07:51:02 music volumio[20926]: [Metrics] WebUI: 6s 620.10ms Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::resetVolumioState Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::getcurrentVolume Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: Volumio Network Manager: Network status updated: 1 Feb 09 07:51:02 music go-librespot[20998]: time="2026-02-09T07:51:02-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:51:02 music volumio[20926]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::pushState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::updateTrackBlock Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrackBlock Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[21009]: Forking 3 albumart workers Feb 09 07:51:02 music volumio-remote-updater[30265]: [2026-02-09 07:51:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770641458 101 Feb 09 07:51:02 music volumio[20926]: 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 Feb 09 07:51:02 music go-librespot[20998]: time="2026-02-09T07:51:02-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:02 music go-librespot[20998]: time="2026-02-09T07:51:02-05:00" level=debug msg="completed challenge" Feb 09 07:51:02 music volumio[20926]: info: Reloading queue from file Feb 09 07:51:02 music volumio[20926]: info: Setting Device type: Raspberry PI Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::setRepeat null single undefined Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::pushState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::setRandom null Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::pushState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:02 music volumio[20926]: info: Listing playlists Feb 09 07:51:02 music volumio[20926]: info: Listing playlists Feb 09 07:51:02 music volumio[20926]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:02 music volumio[20926]: info: CoreStateMachine::pushState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:02 music go-librespot[20998]: time="2026-02-09T07:51:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:02 music volumio[20926]: info: Completed loading Core Plugins Feb 09 07:51:02 music volumio[20926]: info: Preparing to generate the ALSA configuration file Feb 09 07:51:02 music volumio[20926]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:02 music volumio[20926]: info: Discovery: Found device music Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:02 music volumio[20926]: info: Discovery: Found device music Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:02 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:02 music volumio[20926]: info: Asound.conf file unchanged, so no further update is needed Feb 09 07:51:02 music volumio[20926]: info: Output device has changed, restarting MPD Feb 09 07:51:02 music volumio[20926]: info: Output device has changed, restarting Shairport Sync Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:02 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:02 music sudo[21067]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:02 music sudo[21067]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:02 music sudo[21065]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:02 music sudo[21065]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:02 music sudo[21065]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:02 music volumio[20926]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:02 music volumio[20926]: info: ___________ START PLUGINS ___________ Feb 09 07:51:02 music volumio[20926]: info: ControllerMpd::onStart: Initializing MPD Feb 09 07:51:02 music volumio[20926]: info: Creating MPD Configuration file Feb 09 07:51:02 music systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:03 music volumio[20926]: info: [1770641463037] CoreMusicLibrary::Adding element Media Servers Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:03 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:51:03 music sudo[21075]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:03 music sudo[21075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:03 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:51:03 music systemd[1]: mpd.service: Consumed 4.112s CPU time. Feb 09 07:51:03 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:51:03 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:51:03 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:51:03 music sudo[21077]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:03 music sudo[21077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:03 music volumio[20926]: info: UPNP Browser: Client initialized successfully Feb 09 07:51:03 music sudo[21075]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:03 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:51:03 music volumio[20926]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:03 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:51:03 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:51:03 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:51:03 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:51:03 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:51:03 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:51:03 music volumio[20926]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:03 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:03 music volumio[20926]: info: [1770641463269] CoreMusicLibrary::Adding element Last_100 Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:03 music volumio[20926]: info: [1770641463287] CoreMusicLibrary::Adding element Webradio Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:03 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:03 music volumio[20926]: info: Initializing BBC Radios Feb 09 07:51:03 music go-librespot[20998]: time="2026-02-09T07:51:03-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:03 music go-librespot[20998]: time="2026-02-09T07:51:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:54112->104.199.65.9:80: read: connection reset by peer" Feb 09 07:51:03 music volumio[20926]: info: Creating Spotify config file Feb 09 07:51:03 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:03 music sudo[21091]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 09 07:51:03 music sudo[21091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 09 07:51:03 music sudo[21091]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:04 music volumio[20926]: info: Volumio Calling Home Feb 09 07:51:04 music go-librespot[20998]: time="2026-02-09T07:51:04-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:04 music volumio[21028]: Starting albumart workers Feb 09 07:51:04 music go-librespot[20998]: time="2026-02-09T07:51:04-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:04 music go-librespot[20998]: time="2026-02-09T07:51:04-05:00" level=debug msg="completed challenge" Feb 09 07:51:04 music go-librespot[20998]: time="2026-02-09T07:51:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:04 music go-librespot[20998]: time="2026-02-09T07:51:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:04 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:04 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:04 music volumio[21029]: Starting albumart workers Feb 09 07:51:04 music volumio[20926]: info: MPD Permissions set Feb 09 07:51:04 music volumio[20926]: info: MPD Permissions set Feb 09 07:51:04 music volumio[20926]: info: Spotify config file written Feb 09 07:51:04 music volumio[21027]: Starting albumart workers Feb 09 07:51:04 music sudo[21111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 07:51:04 music volumio[20926]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 09 07:51:04 music sudo[21111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:04 music volumio[20926]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:04 music go-librespot[21118]: go-librespot daemon starting... Feb 09 07:51:04 music volumio[20926]: info: No need to fix Spotify hosts Feb 09 07:51:04 music sudo[21111]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:04 music go-librespot[21124]: time="2026-02-09T07:51:04-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:04 music go-librespot[21124]: time="2026-02-09T07:51:04-05:00" level=debug msg="app state loaded" Feb 09 07:51:04 music go-librespot[21124]: time="2026-02-09T07:51:04-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:04 music go-librespot[21124]: time="2026-02-09T07:51:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp [2600:1901:1:7c5::]:443: connect: cannot assign requested address" Feb 09 07:51:04 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:04 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:05 music volumio[20926]: info: Volumio called home Feb 09 07:51:05 music volumio[20926]: info: Starting Shairport Sync Feb 09 07:51:05 music volumio[20926]: info: Starting Shairport Sync Feb 09 07:51:05 music volumio[20926]: info: Starting Shairport Sync Feb 09 07:51:05 music sudo[21143]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:05 music sudo[21143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:05 music sudo[21141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:05 music sudo[21141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:05 music volumio[20926]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 09 07:51:05 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:51:05 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:51:05 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:05 music systemd[1]: shairport-sync.service: Consumed 1.890s CPU time. Feb 09 07:51:05 music sudo[21147]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:05 music sudo[21147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:05 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:05 music sudo[21141]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:05 music sudo[21143]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:05 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:51:05 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:51:05 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:05 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:05 music volumio[20926]: info: Shairport-Sync Started Feb 09 07:51:05 music sudo[21147]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:05 music volumio[20926]: Error adding Membership: Error: addMembership EINVAL Feb 09 07:51:05 music volumio[20926]: info: Shairport-Sync Started Feb 09 07:51:05 music volumio[20926]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:05 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:05 music volumio[20926]: info: Shairport-Sync Started Feb 09 07:51:07 music mpd[21106]: 2026-02-09T07:51:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 09 07:51:07 music systemd[1]: Started mpd.service - Music Player Daemon. Feb 09 07:51:07 music sudo[21067]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:07 music sudo[21077]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:07 music volumio[20926]: info: Completed starting Core Plugins Feb 09 07:51:07 music volumio[20926]: info: ------------------------------------------- Feb 09 07:51:07 music volumio[20926]: info: ----- MyVolumio plugins startup ---- Feb 09 07:51:07 music volumio[20926]: info: ------------------------------------------- Feb 09 07:51:07 music volumio[20926]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 09 07:51:07 music volumio[20926]: error: MPD error: The expression evaluated to a falsy value: Feb 09 07:51:07 music volumio[20926]: assert.ok(self.idling) Feb 09 07:51:07 music volumio[20926]: error: The expression evaluated to a falsy value: Feb 09 07:51:07 music volumio[20926]: assert.ok(self.idling) Feb 09 07:51:07 music volumio[20926]: error: updateQueue error: null Feb 09 07:51:07 music volumio[20926]: info: MPD running with PID21106 Feb 09 07:51:07 music volumio[20926]: ,establishing connection Feb 09 07:51:07 music volumio[20926]: error: updateQueue error: null Feb 09 07:51:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Feb 09 07:51:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:08 music go-librespot[21183]: go-librespot daemon starting... Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="app state loaded" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:08 music volumio[20926]: info: go-librespot daemon successfully initialized Feb 09 07:51:08 music sudo[21208]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:51:08 music sudo[21208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:08 music sudo[21208]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:08 music sudo[21210]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:51:08 music sudo[21210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:08 music sudo[21210]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:08 music sudo[21213]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 09 07:51:08 music sudo[21213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=info msg="zeroconf server listening on port 35673" Feb 09 07:51:08 music sudo[21213]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:08 music volumio[20926]: info: Upmpdcli Daemon Started Feb 09 07:51:08 music volumio[20926]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:08 music volumio[20926]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="obtained new client token: AACs9O2pBpqxMvM2V3H91xncDBLxFinr6+vUfP+e/blSRieM7r/9YbO5OHmskzUP2+fmD+4UL0aKTyJoBJsH4sQ+fjh7qlGgcTCSc+OlTKkPrdjDgVwoq102RDrNgafvf1aNKj/YD0aEEiAXCKgVcJcso1KPW91baWW8zbHTMbYv7mlFaLNrVEnAzsK+eFIIdg+dgQPol5UFp+mf3dKo9Twj7H19kPsV4wOg2Kdj1YqGnO4lTI5zM7Y=" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=debug msg="completed challenge" Feb 09 07:51:08 music go-librespot[21184]: time="2026-02-09T07:51:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:09 music go-librespot[21184]: time="2026-02-09T07:51:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:09 music go-librespot[21184]: time="2026-02-09T07:51:09-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:09 music go-librespot[21184]: time="2026-02-09T07:51:09-05:00" level=debug msg="completed challenge" Feb 09 07:51:09 music go-librespot[21184]: time="2026-02-09T07:51:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="completed challenge" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:10 music sudo[21217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:10 music sudo[21217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:10 music sudo[21219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:10 music sudo[21219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:10 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:51:10 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:51:10 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:10 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:10 music sudo[21217]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:10 music mpd_monitor.sh[21222]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:51:10 music sudo[21219]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:10 music volumio[20926]: info: Successfully started MPD Monitor Feb 09 07:51:10 music volumio[20926]: info: Successfully started MPD Monitor Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=debug msg="completed challenge" Feb 09 07:51:10 music go-librespot[21184]: time="2026-02-09T07:51:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:11 music volumio[20926]: info: Initializing connection to go-librespot Websocket Feb 09 07:51:11 music go-librespot[21184]: time="2026-02-09T07:51:11-05:00" level=debug msg="new websocket client" Feb 09 07:51:11 music volumio[20926]: info: Connection to go-librespot Websocket established Feb 09 07:51:11 music go-librespot[21184]: time="2026-02-09T07:51:11-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:51:11 music go-librespot[21184]: time="2026-02-09T07:51:11-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:11 music go-librespot[21184]: time="2026-02-09T07:51:11-05:00" level=debug msg="completed challenge" Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:12 music volumio[20926]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=debug msg="completed challenge" Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:12 music go-librespot[21184]: time="2026-02-09T07:51:12-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:12 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:12 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:12 music volumio[20926]: info: Connection to go-librespot Websocket closed Feb 09 07:51:14 music volumio[20926]: info: Getting Spotify volume Feb 09 07:51:14 music volumio[20926]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:51:14 music volumio[20926]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:51:14 music volumio[20926]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 09 07:51:14 music volumio[20926]: errno: -111, Feb 09 07:51:14 music volumio[20926]: code: 'ECONNREFUSED', Feb 09 07:51:14 music volumio[20926]: syscall: 'connect', Feb 09 07:51:14 music volumio[20926]: address: '127.0.0.1', Feb 09 07:51:14 music volumio[20926]: port: 9879, Feb 09 07:51:14 music volumio[20926]: response: undefined Feb 09 07:51:14 music volumio[20926]: } Feb 09 07:51:14 music volumio[20926]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:51:15 music sudo[21240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 07:50' Feb 09 07:51:15 music sudo[21240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:15 music sudo[21240]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:16 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Feb 09 07:51:16 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:16 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:16 music go-librespot[21248]: go-librespot daemon starting... Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="app state loaded" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:16 music volumio-remote-updater[30265]: [2026-02-09 07:51:16] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 09 07:51:16 music volumio-remote-updater[30265]: [2026-02-09 07:51:16] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 09 07:51:16 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:16 music systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 09 07:51:16 music systemd[1]: volumio.service: Consumed 23.518s CPU time. Feb 09 07:51:16 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:51:16 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=info msg="zeroconf server listening on port 40445" Feb 09 07:51:16 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 52538. Feb 09 07:51:16 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:51:16 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 09 07:51:16 music systemd[1]: volumio.service: Consumed 23.518s CPU time. Feb 09 07:51:16 music systemd[1]: Started volumio.service - Volumio Backend Module. Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="obtained new client token: AADIZ6DAm0B1otWDbLnRR4Orq2uOhkF4bsGdiCwK4aj2H+r7tbW9JdkDAqbjCcmz0IcFhy85EeO4ulh62sABZjdYSubEEeX75M2Qxqs+6XvnODjqut6JeFG7v1C8J0z0zOSZbZyBWBoF0ULHzKSzZ10V53NFnDZZnuSzxoUGmpC9hudeITN/gaPsrnpIRXEp7nJyKZJXIit3jT/i1Omeya+RtJUjNrIAp1+9tPwTMmMYy56mC7Sy3Hk=" Feb 09 07:51:16 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=debug msg="completed challenge" Feb 09 07:51:16 music go-librespot[21249]: time="2026-02-09T07:51:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:17 music go-librespot[21249]: time="2026-02-09T07:51:17-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Feb 09 07:51:17 music go-librespot[21249]: time="2026-02-09T07:51:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:17 music go-librespot[21249]: time="2026-02-09T07:51:17-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:17 music go-librespot[21249]: time="2026-02-09T07:51:17-05:00" level=debug msg="completed challenge" Feb 09 07:51:17 music go-librespot[21249]: time="2026-02-09T07:51:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:18 music go-librespot[21249]: time="2026-02-09T07:51:18-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:18 music go-librespot[21249]: time="2026-02-09T07:51:18-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:18 music go-librespot[21249]: time="2026-02-09T07:51:18-05:00" level=debug msg="completed challenge" Feb 09 07:51:18 music go-librespot[21249]: time="2026-02-09T07:51:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:18 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:18 music volumio[21267]: info: ----- Volumio3 ---- Feb 09 07:51:18 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:18 music volumio[21267]: info: ----- System startup ---- Feb 09 07:51:18 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.241.202:443: connect: connection refused" Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=debug msg="completed challenge" Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:19 music volumio[21267]: info: MYVOLUMIO Environment detected Feb 09 07:51:19 music volumio[21267]: info: Plugin folders cleanup Feb 09 07:51:19 music volumio[21267]: info: Scanning into folder /volumio/app/plugins/ Feb 09 07:51:19 music volumio[21267]: info: Scanning category audio_interface Feb 09 07:51:19 music volumio[21267]: info: Scanning category miscellanea Feb 09 07:51:19 music volumio[21267]: info: Scanning category music_service Feb 09 07:51:19 music volumio[21267]: info: Scanning category plugins.json Feb 09 07:51:19 music volumio[21267]: info: Scanning category system_controller Feb 09 07:51:19 music volumio[21267]: info: Scanning category user_interface Feb 09 07:51:19 music volumio[21267]: info: Scanning into folder /data/plugins/ Feb 09 07:51:19 music volumio[21267]: info: Scanning category music_service Feb 09 07:51:19 music volumio[21267]: info: Plugin folders cleanup completed Feb 09 07:51:19 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:19 music volumio[21267]: info: ----- Core plugins startup ---- Feb 09 07:51:19 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:19 music volumio[21267]: info: Loading plugins from folder /volumio/app/plugins/ Feb 09 07:51:19 music volumio[21267]: info: Adding plugin upnp to MyMusic Plugins Feb 09 07:51:19 music volumio[21267]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 09 07:51:19 music volumio[21267]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 09 07:51:19 music volumio[21267]: info: Loading plugins from folder /data/plugins/ Feb 09 07:51:19 music volumio[21267]: info: Loading plugin "system"... Feb 09 07:51:19 music volumio[21267]: info: Loading plugin "appearance"... Feb 09 07:51:19 music go-librespot[21249]: time="2026-02-09T07:51:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=debug msg="completed challenge" Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "network"... Feb 09 07:51:20 music volumio[21267]: info: Refreshing Cached IP Addresses Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:20 music sudo[21296]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:51:20 music sudo[21296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:20 music sudo[21298]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:51:20 music sudo[21298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:20 music sudo[21296]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:20 music sudo[21298]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "services"... Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "alsa_controller"... Feb 09 07:51:20 music sudo[21306]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=debug msg="completed challenge" Feb 09 07:51:20 music sudo[21306]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:20 music go-librespot[21249]: time="2026-02-09T07:51:20-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:20 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:20 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:20 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "wizard"... Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "networkfs"... Feb 09 07:51:20 music volumio[21267]: info: Starting Udev Watcher for removable devices Feb 09 07:51:20 music volumio[21267]: info: Ignoring mount for partition: boot Feb 09 07:51:20 music volumio[21267]: info: Ignoring mount for partition: volumio Feb 09 07:51:20 music volumio[21267]: info: Ignoring mount for partition: volumio_data Feb 09 07:51:20 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "volumio_command_line_client"... Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "upnp"... Feb 09 07:51:20 music volumio[21267]: info: [1770641480886] Starting Upmpd Daemon Feb 09 07:51:20 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "my_music"... Feb 09 07:51:20 music volumio[21267]: info: Loading plugin "mpd"... Feb 09 07:51:21 music volumio-remote-updater[30265]: [2026-02-09 07:51:21] [connect] Successful connection Feb 09 07:51:21 music volumio[21267]: info: Loading plugin "upnp_browser"... Feb 09 07:51:21 music sudo[21306]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:22 music volumio[21267]: info: Starting UPNP Browser Feb 09 07:51:22 music volumio[21267]: info: Loading plugin "alarm-clock"... Feb 09 07:51:22 music volumio[21267]: info: Loading plugin "airplay_emulation"... Feb 09 07:51:22 music volumio[21267]: info: Starting Shairport Sync Feb 09 07:51:22 music volumio[21267]: info: Loading plugin "last_100"... Feb 09 07:51:22 music volumio[21267]: info: Loading plugin "webradio"... Feb 09 07:51:23 music volumio[21267]: info: Loading plugin "i2s_dacs"... Feb 09 07:51:23 music volumio[21267]: info: I2S DAC not set, start Auto-detection Feb 09 07:51:23 music volumio[21267]: info: Loading plugin "volumiodiscovery"... Feb 09 07:51:23 music volumio[21267]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:23 music volumio[21267]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:23 music volumio[21267]: *** WARNING *** For more information see Feb 09 07:51:23 music volumio[21267]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:23 music volumio[21267]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:23 music volumio[21267]: *** WARNING *** For more information see Feb 09 07:51:23 music node[21267]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:23 music node[21267]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:23 music node[21267]: *** WARNING *** For more information see Feb 09 07:51:23 music node[21267]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:23 music node[21267]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:23 music node[21267]: *** WARNING *** For more information see Feb 09 07:51:23 music volumio[21267]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 09 07:51:23 music volumio[21267]: info: Discovery: Started advertising with name: music Feb 09 07:51:23 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:23 music volumio[21267]: info: Loading plugin "spop"... Feb 09 07:51:23 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Feb 09 07:51:23 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:23 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:23 music go-librespot[21331]: go-librespot daemon starting... Feb 09 07:51:23 music go-librespot[21332]: time="2026-02-09T07:51:23-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:23 music go-librespot[21332]: time="2026-02-09T07:51:23-05:00" level=debug msg="app state loaded" Feb 09 07:51:23 music go-librespot[21332]: time="2026-02-09T07:51:23-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=info msg="zeroconf server listening on port 45575" Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "outputs"... Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "albumart"... Feb 09 07:51:24 music volumio[21267]: info: Plugin example_plugin is not enabled Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "inputs"... Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "updater_comm"... Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="obtained new client token: AACsPd6sLtnR09gLTiZFq8UJkPzA3mmUqFjC9kSnOGEV0h0PHEK/MM2XeeG5Ihb+muBols3nGr2tuPP7J5qKQ/f7tF9vQ+A9JDYRLkaBdoocBD2Wq/L/Kbh6i3lJqw7Pmeyjb7lIWZ5t3DaKZeMga6fNT61AKl5bTKlfgf8NvrfR0OYH8uPatx0oRYR6Ai0NLP0Q/nHK8gbXrgFfPfOUNLiultbS+bVGeB8JfBysvQXpigKZXv/pz/E=" Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:24 music volumio[21267]: info: Plugin mpdemulation is not enabled Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "rest_api"... Feb 09 07:51:24 music volumio[21267]: info: Loading plugin "websocket"... Feb 09 07:51:24 music volumio[21267]: info: Starting Socket.io Server version 1.7.4 Feb 09 07:51:24 music volumio[21267]: info: Loading i18n strings for locale en Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:24 music volumio[21267]: Updating browse sources language Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=debug msg="completed challenge" Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:24 music go-librespot[21332]: time="2026-02-09T07:51:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::initPlayerControls Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:24 music volumio[21267]: Express server listening on port 3000 Feb 09 07:51:24 music volumio[21267]: [Metrics] WebUI: 6s 662.63ms Feb 09 07:51:24 music volumio[21267]: info: CoreStateMachine::resetVolumioState Feb 09 07:51:24 music volumio[21267]: info: CoreStateMachine::getcurrentVolume Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:24 music volumio[21267]: info: Volumio Network Manager: Network status updated: 1 Feb 09 07:51:24 music volumio[21267]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:24 music volumio[21267]: info: CoreStateMachine::pushState Feb 09 07:51:24 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:24 music volumio[21267]: info: CoreStateMachine::updateTrackBlock Feb 09 07:51:24 music volumio[21267]: info: CorePlayQueue::getTrackBlock Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:24 music volumio[21341]: Forking 3 albumart workers Feb 09 07:51:24 music volumio[21267]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:24 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio-remote-updater[30265]: [2026-02-09 07:51:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770641481 101 Feb 09 07:51:25 music volumio[21267]: 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 Feb 09 07:51:25 music volumio[21267]: info: Reloading queue from file Feb 09 07:51:25 music volumio[21267]: info: CoreStateMachine::setRepeat null single undefined Feb 09 07:51:25 music volumio[21267]: info: CoreStateMachine::pushState Feb 09 07:51:25 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:25 music volumio[21267]: info: CoreStateMachine::setRandom null Feb 09 07:51:25 music volumio[21267]: info: CoreStateMachine::pushState Feb 09 07:51:25 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:25 music volumio[21267]: info: Setting Device type: Raspberry PI Feb 09 07:51:25 music volumio[21267]: info: Listing playlists Feb 09 07:51:25 music volumio[21267]: info: Listing playlists Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:25 music volumio[21267]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:25 music volumio[21267]: info: CoreStateMachine::pushState Feb 09 07:51:25 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:25 music volumio[21267]: info: Completed loading Core Plugins Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="completed challenge" Feb 09 07:51:25 music volumio[21267]: info: Preparing to generate the ALSA configuration file Feb 09 07:51:25 music volumio[21267]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:25 music volumio[21267]: info: Discovery: Found device music Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:25 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio[21267]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:25 music volumio[21267]: info: Discovery: Found device music Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:25 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:25 music volumio[21267]: info: Asound.conf file unchanged, so no further update is needed Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:25 music volumio[21267]: info: Output device has changed, restarting MPD Feb 09 07:51:25 music volumio[21267]: info: Output device has changed, restarting Shairport Sync Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:25 music sudo[21397]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:25 music sudo[21397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:25 music sudo[21398]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:25 music sudo[21398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:25 music sudo[21397]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:25 music volumio[21267]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:25 music volumio[21267]: info: ___________ START PLUGINS ___________ Feb 09 07:51:25 music volumio[21267]: info: ControllerMpd::onStart: Initializing MPD Feb 09 07:51:25 music volumio[21267]: info: Creating MPD Configuration file Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:25 music volumio[21267]: info: [1770641485462] CoreMusicLibrary::Adding element Media Servers Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:25 music systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 09 07:51:25 music sudo[21407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:25 music volumio[21267]: info: UPNP Browser: Client initialized successfully Feb 09 07:51:25 music sudo[21407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:25 music sudo[21407]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:25 music sudo[21408]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:25 music sudo[21408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:25 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:51:25 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:51:25 music systemd[1]: mpd.service: Consumed 4.027s CPU time. Feb 09 07:51:25 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:51:25 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:51:25 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:51:25 music volumio[21267]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:25 music volumio[21267]: info: [1770641485620] CoreMusicLibrary::Adding element Last_100 Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:25 music volumio[21267]: info: [1770641485625] CoreMusicLibrary::Adding element Webradio Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:25 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:25 music volumio[21267]: info: Initializing BBC Radios Feb 09 07:51:25 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:51:25 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:51:25 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:51:25 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:51:25 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:51:25 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:51:25 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:51:25 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:25 music volumio[21267]: info: Creating Spotify config file Feb 09 07:51:25 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:25 music go-librespot[21332]: time="2026-02-09T07:51:25-05:00" level=debug msg="completed challenge" Feb 09 07:51:26 music sudo[21427]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 09 07:51:26 music sudo[21427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 09 07:51:26 music sudo[21427]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:26 music go-librespot[21332]: time="2026-02-09T07:51:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:26 music volumio[21267]: info: Volumio Calling Home Feb 09 07:51:26 music go-librespot[21332]: time="2026-02-09T07:51:26-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:26 music go-librespot[21332]: time="2026-02-09T07:51:26-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:26 music go-librespot[21332]: time="2026-02-09T07:51:26-05:00" level=debug msg="completed challenge" Feb 09 07:51:26 music go-librespot[21332]: time="2026-02-09T07:51:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:26 music volumio[21267]: info: MPD Permissions set Feb 09 07:51:26 music volumio[21267]: info: MPD Permissions set Feb 09 07:51:26 music volumio[21360]: Starting albumart workers Feb 09 07:51:26 music volumio[21267]: info: Volumio called home Feb 09 07:51:26 music volumio[21267]: info: Spotify config file written Feb 09 07:51:26 music volumio[21358]: Starting albumart workers Feb 09 07:51:27 music volumio[21267]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music sudo[21442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 07:51:27 music sudo[21442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:27 music volumio[21267]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:27 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:27 music go-librespot[21450]: go-librespot daemon starting... Feb 09 07:51:27 music volumio[21267]: info: No need to fix Spotify hosts Feb 09 07:51:27 music sudo[21442]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=debug msg="app state loaded" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:27 music volumio[21359]: Starting albumart workers Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=info msg="zeroconf server listening on port 45889" Feb 09 07:51:27 music go-librespot[21455]: time="2026-02-09T07:51:27-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp [2600:1901:1:7c5::]:443: connect: cannot assign requested address" Feb 09 07:51:27 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:27 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:27 music volumio[21267]: info: Starting Shairport Sync Feb 09 07:51:27 music volumio[21267]: info: Starting Shairport Sync Feb 09 07:51:28 music volumio[21267]: info: Starting Shairport Sync Feb 09 07:51:28 music sudo[21465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:28 music sudo[21465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:28 music sudo[21467]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:28 music volumio[21267]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 09 07:51:28 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:51:28 music sudo[21467]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:28 music sudo[21469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:28 music sudo[21469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:28 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:51:28 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:28 music systemd[1]: shairport-sync.service: Consumed 1.844s CPU time. Feb 09 07:51:28 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:28 music sudo[21465]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:28 music volumio[21267]: info: Shairport-Sync Started Feb 09 07:51:28 music volumio[21267]: Error adding Membership: Error: addMembership EINVAL Feb 09 07:51:28 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:51:28 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:51:28 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:28 music volumio[21267]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:28 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:28 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:28 music sudo[21469]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:28 music sudo[21467]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:28 music volumio[21267]: info: Shairport-Sync Started Feb 09 07:51:28 music volumio[21267]: info: Shairport-Sync Started Feb 09 07:51:28 music volumio[21267]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:28 music volumio[21267]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:30 music mpd[21437]: 2026-02-09T07:51:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 09 07:51:30 music systemd[1]: Started mpd.service - Music Player Daemon. Feb 09 07:51:30 music sudo[21398]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:30 music sudo[21408]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:30 music volumio[21267]: info: Completed starting Core Plugins Feb 09 07:51:30 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:30 music volumio[21267]: info: ----- MyVolumio plugins startup ---- Feb 09 07:51:30 music volumio[21267]: info: ------------------------------------------- Feb 09 07:51:30 music volumio[21267]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 09 07:51:30 music volumio[21267]: error: MPD error: The expression evaluated to a falsy value: Feb 09 07:51:30 music volumio[21267]: assert.ok(self.idling) Feb 09 07:51:30 music volumio[21267]: error: The expression evaluated to a falsy value: Feb 09 07:51:30 music volumio[21267]: assert.ok(self.idling) Feb 09 07:51:30 music volumio[21267]: info: MPD running with PID21437 Feb 09 07:51:30 music volumio[21267]: ,establishing connection Feb 09 07:51:30 music volumio[21267]: error: updateQueue error: null Feb 09 07:51:30 music volumio[21267]: error: updateQueue error: null Feb 09 07:51:30 music sudo[21542]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:51:30 music sudo[21542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:30 music sudo[21542]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:30 music sudo[21544]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:51:30 music sudo[21544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:30 music sudo[21544]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:30 music volumio[21267]: info: go-librespot daemon successfully initialized Feb 09 07:51:30 music sudo[21547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 09 07:51:30 music sudo[21547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:30 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 09 07:51:30 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:31 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:31 music go-librespot[21550]: go-librespot daemon starting... Feb 09 07:51:31 music sudo[21547]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:31 music volumio[21267]: info: Upmpdcli Daemon Started Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="app state loaded" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=info msg="zeroconf server listening on port 39885" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="obtained new client token: AAAEGCy8FDvP8tf52qw4je3D6kao8GivwNYhbH6mqm6cYLgJ5hDhsxoKvVUZXavUc2EKnnpi9EiYg6BewQA3aMx5Op1zyO0709sr+9zEdnNyHA4mJQTtjVYsIGd0PnmXs6XVUiwkJIRSB7CeommS4VA/dAvYVrNwpz3zc9a5Vh0p0aTeKeTUh3302UX2NF1ttsuMa3tXHTfegu6/cPGnpuJhVDYYpH1ZtlXylPmNl/a9+6flQdvzyYg=" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=debug msg="completed challenge" Feb 09 07:51:31 music go-librespot[21551]: time="2026-02-09T07:51:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:32 music go-librespot[21551]: time="2026-02-09T07:51:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:32 music go-librespot[21551]: time="2026-02-09T07:51:32-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:32 music go-librespot[21551]: time="2026-02-09T07:51:32-05:00" level=debug msg="completed challenge" Feb 09 07:51:32 music go-librespot[21551]: time="2026-02-09T07:51:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:33 music sudo[21561]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:33 music sudo[21561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:33 music sudo[21563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:33 music sudo[21563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:33 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="completed challenge" Feb 09 07:51:33 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:51:33 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:33 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:33 music sudo[21561]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:33 music sudo[21563]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:33 music mpd_monitor.sh[21566]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:51:33 music volumio[21267]: info: Successfully started MPD Monitor Feb 09 07:51:33 music volumio[21267]: info: Successfully started MPD Monitor Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="completed challenge" Feb 09 07:51:33 music volumio[21267]: info: Initializing connection to go-librespot Websocket Feb 09 07:51:33 music volumio[21267]: info: Connection to go-librespot Websocket established Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=debug msg="new websocket client" Feb 09 07:51:33 music go-librespot[21551]: time="2026-02-09T07:51:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:34 music go-librespot[21551]: time="2026-02-09T07:51:34-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:51:34 music go-librespot[21551]: time="2026-02-09T07:51:34-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:34 music go-librespot[21551]: time="2026-02-09T07:51:34-05:00" level=debug msg="completed challenge" Feb 09 07:51:35 music go-librespot[21551]: time="2026-02-09T07:51:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:35 music volumio[21267]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 09 07:51:35 music go-librespot[21551]: time="2026-02-09T07:51:35-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:51:35 music go-librespot[21551]: time="2026-02-09T07:51:35-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:35 music go-librespot[21551]: time="2026-02-09T07:51:35-05:00" level=debug msg="completed challenge" Feb 09 07:51:36 music go-librespot[21551]: time="2026-02-09T07:51:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:36 music go-librespot[21551]: time="2026-02-09T07:51:36-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:36 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:36 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:36 music volumio[21267]: info: Connection to go-librespot Websocket closed Feb 09 07:51:36 music volumio[21267]: info: Getting Spotify volume Feb 09 07:51:36 music volumio[21267]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:51:37 music volumio[21267]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:51:37 music volumio[21267]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 09 07:51:37 music volumio[21267]: errno: -111, Feb 09 07:51:37 music volumio[21267]: code: 'ECONNREFUSED', Feb 09 07:51:37 music volumio[21267]: syscall: 'connect', Feb 09 07:51:37 music volumio[21267]: address: '127.0.0.1', Feb 09 07:51:37 music volumio[21267]: port: 9879, Feb 09 07:51:37 music volumio[21267]: response: undefined Feb 09 07:51:37 music volumio[21267]: } Feb 09 07:51:37 music volumio[21267]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:51:37 music sudo[21584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 07:50' Feb 09 07:51:37 music sudo[21584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:38 music sudo[21584]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:38 music volumio-remote-updater[30265]: [2026-02-09 07:51:38] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 09 07:51:38 music volumio-remote-updater[30265]: [2026-02-09 07:51:38] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 09 07:51:38 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:38 music systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 09 07:51:38 music systemd[1]: volumio.service: Consumed 23.484s CPU time. Feb 09 07:51:38 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:51:38 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 52539. Feb 09 07:51:38 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:51:38 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 09 07:51:38 music systemd[1]: volumio.service: Consumed 23.484s CPU time. Feb 09 07:51:38 music systemd[1]: Started volumio.service - Volumio Backend Module. Feb 09 07:51:39 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Feb 09 07:51:39 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:39 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:39 music go-librespot[21605]: go-librespot daemon starting... Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="app state loaded" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=info msg="zeroconf server listening on port 38089" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="obtained new client token: AAAiH4QEOXtoQ+p9gguKfE1l/CKTZfwayfo+98PVHzjGpm29WwLdgJrNVX/dPkpaqEU6+4QQwTB2tj1NW6xfvh50hrNBYbsiliKK8itOnZra2seY10T2DcIW1RR+MH4fAh6pDi9kFn1hf6qF68jo7RW6BCN/8+kDrLu09wnn6EXU390CUV+4ugMmkXl2TrLgDGUOrtd3nnQQW7aOCsj6XOUhpkk9gqHQUUINd/OIMncgBmgoeEJG9cw=" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=debug msg="completed challenge" Feb 09 07:51:39 music go-librespot[21606]: time="2026-02-09T07:51:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:40 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:40 music volumio[21595]: info: ----- Volumio3 ---- Feb 09 07:51:40 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:40 music volumio[21595]: info: ----- System startup ---- Feb 09 07:51:40 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:40 music go-librespot[21606]: time="2026-02-09T07:51:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:40 music go-librespot[21606]: time="2026-02-09T07:51:40-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:40 music go-librespot[21606]: time="2026-02-09T07:51:40-05:00" level=debug msg="completed challenge" Feb 09 07:51:40 music go-librespot[21606]: time="2026-02-09T07:51:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:41 music volumio[21595]: info: MYVOLUMIO Environment detected Feb 09 07:51:41 music go-librespot[21606]: time="2026-02-09T07:51:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:41 music volumio[21595]: info: Plugin folders cleanup Feb 09 07:51:41 music volumio[21595]: info: Scanning into folder /volumio/app/plugins/ Feb 09 07:51:41 music volumio[21595]: info: Scanning category audio_interface Feb 09 07:51:41 music volumio[21595]: info: Scanning category miscellanea Feb 09 07:51:41 music volumio[21595]: info: Scanning category music_service Feb 09 07:51:41 music volumio[21595]: info: Scanning category plugins.json Feb 09 07:51:41 music volumio[21595]: info: Scanning category system_controller Feb 09 07:51:41 music volumio[21595]: info: Scanning category user_interface Feb 09 07:51:41 music volumio[21595]: info: Scanning into folder /data/plugins/ Feb 09 07:51:41 music volumio[21595]: info: Scanning category music_service Feb 09 07:51:41 music volumio[21595]: info: Plugin folders cleanup completed Feb 09 07:51:41 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:41 music volumio[21595]: info: ----- Core plugins startup ---- Feb 09 07:51:41 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:41 music volumio[21595]: info: Loading plugins from folder /volumio/app/plugins/ Feb 09 07:51:41 music volumio[21595]: info: Adding plugin upnp to MyMusic Plugins Feb 09 07:51:41 music volumio[21595]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 09 07:51:41 music volumio[21595]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 09 07:51:41 music volumio[21595]: info: Loading plugins from folder /data/plugins/ Feb 09 07:51:41 music volumio[21595]: info: Loading plugin "system"... Feb 09 07:51:41 music go-librespot[21606]: time="2026-02-09T07:51:41-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:41 music go-librespot[21606]: time="2026-02-09T07:51:41-05:00" level=debug msg="completed challenge" Feb 09 07:51:41 music volumio[21595]: info: Loading plugin "appearance"... Feb 09 07:51:41 music go-librespot[21606]: time="2026-02-09T07:51:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:41 music go-librespot[21606]: time="2026-02-09T07:51:41-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 09 07:51:42 music go-librespot[21606]: time="2026-02-09T07:51:42-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:42 music go-librespot[21606]: time="2026-02-09T07:51:42-05:00" level=debug msg="completed challenge" Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "network"... Feb 09 07:51:42 music volumio[21595]: info: Refreshing Cached IP Addresses Feb 09 07:51:42 music sudo[21629]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:51:42 music sudo[21629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:42 music sudo[21631]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:51:42 music sudo[21631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:42 music sudo[21629]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:42 music sudo[21631]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "services"... Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "alsa_controller"... Feb 09 07:51:42 music go-librespot[21606]: time="2026-02-09T07:51:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:42 music sudo[21639]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 09 07:51:42 music sudo[21639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:42 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "wizard"... Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "networkfs"... Feb 09 07:51:42 music volumio[21595]: info: Starting Udev Watcher for removable devices Feb 09 07:51:42 music volumio[21595]: info: Ignoring mount for partition: boot Feb 09 07:51:42 music volumio[21595]: info: Ignoring mount for partition: volumio Feb 09 07:51:42 music volumio[21595]: info: Ignoring mount for partition: volumio_data Feb 09 07:51:42 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "volumio_command_line_client"... Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "upnp"... Feb 09 07:51:42 music volumio[21595]: info: [1770641502537] Starting Upmpd Daemon Feb 09 07:51:42 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "my_music"... Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "mpd"... Feb 09 07:51:42 music volumio[21595]: info: Loading plugin "upnp_browser"... Feb 09 07:51:42 music sudo[21639]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:43 music go-librespot[21606]: time="2026-02-09T07:51:43-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 09 07:51:43 music volumio-remote-updater[30265]: [2026-02-09 07:51:43] [connect] Successful connection Feb 09 07:51:43 music go-librespot[21606]: time="2026-02-09T07:51:43-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:43 music go-librespot[21606]: time="2026-02-09T07:51:43-05:00" level=debug msg="completed challenge" Feb 09 07:51:43 music go-librespot[21606]: time="2026-02-09T07:51:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:43 music go-librespot[21606]: time="2026-02-09T07:51:43-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:51:44 music go-librespot[21606]: time="2026-02-09T07:51:44-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:44 music go-librespot[21606]: time="2026-02-09T07:51:44-05:00" level=debug msg="completed challenge" Feb 09 07:51:44 music go-librespot[21606]: time="2026-02-09T07:51:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:44 music go-librespot[21606]: time="2026-02-09T07:51:44-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:44 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:44 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:44 music volumio[21595]: info: Starting UPNP Browser Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "alarm-clock"... Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "airplay_emulation"... Feb 09 07:51:44 music volumio[21595]: info: Starting Shairport Sync Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "last_100"... Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "webradio"... Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "i2s_dacs"... Feb 09 07:51:44 music volumio[21595]: info: I2S DAC not set, start Auto-detection Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "volumiodiscovery"... Feb 09 07:51:44 music volumio[21595]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:44 music node[21595]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:44 music volumio[21595]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:44 music volumio[21595]: *** WARNING *** For more information see Feb 09 07:51:44 music volumio[21595]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:44 music volumio[21595]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:44 music volumio[21595]: *** WARNING *** For more information see Feb 09 07:51:44 music volumio[21595]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 09 07:51:44 music node[21595]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:44 music node[21595]: *** WARNING *** For more information see Feb 09 07:51:44 music node[21595]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:51:44 music node[21595]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:51:44 music node[21595]: *** WARNING *** For more information see Feb 09 07:51:44 music volumio[21595]: info: Discovery: Started advertising with name: music Feb 09 07:51:44 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:51:44 music volumio[21595]: info: Loading plugin "spop"... Feb 09 07:51:45 music volumio[21595]: info: Loading plugin "outputs"... Feb 09 07:51:45 music volumio[21595]: info: Loading plugin "albumart"... Feb 09 07:51:45 music volumio[21595]: info: Plugin example_plugin is not enabled Feb 09 07:51:46 music volumio[21595]: info: Loading plugin "inputs"... Feb 09 07:51:46 music volumio[21595]: info: Loading plugin "updater_comm"... Feb 09 07:51:46 music volumio[21595]: info: Plugin mpdemulation is not enabled Feb 09 07:51:46 music volumio[21595]: info: Loading plugin "rest_api"... Feb 09 07:51:46 music volumio[21595]: info: Loading plugin "websocket"... Feb 09 07:51:46 music volumio[21595]: info: Starting Socket.io Server version 1.7.4 Feb 09 07:51:46 music volumio[21595]: info: Loading i18n strings for locale en Feb 09 07:51:46 music volumio[21595]: Updating browse sources language Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::initPlayerControls Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:46 music volumio[21595]: Express server listening on port 3000 Feb 09 07:51:46 music volumio[21595]: [Metrics] WebUI: 6s 590.61ms Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::resetVolumioState Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::getcurrentVolume Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: Volumio Network Manager: Network status updated: 1 Feb 09 07:51:46 music volumio[21664]: Forking 3 albumart workers Feb 09 07:51:46 music volumio-remote-updater[30265]: [2026-02-09 07:51:46] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770641503 101 Feb 09 07:51:46 music volumio[21595]: 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 Feb 09 07:51:46 music volumio[21595]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::pushState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::updateTrackBlock Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrackBlock Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:51:46 music volumio[21595]: info: Reloading queue from file Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::setRepeat null single undefined Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::pushState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::setRandom null Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::pushState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:46 music volumio[21595]: info: Setting Device type: Raspberry PI Feb 09 07:51:46 music volumio[21595]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:51:46 music volumio[21595]: info: CoreStateMachine::pushState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioPushState Feb 09 07:51:46 music volumio[21595]: info: Completed loading Core Plugins Feb 09 07:51:46 music volumio[21595]: info: Preparing to generate the ALSA configuration file Feb 09 07:51:46 music volumio[21595]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:46 music volumio[21595]: info: Discovery: Found device music Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:51:46 music volumio[21595]: info: Discovery: Found device music Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:46 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:46 music volumio[21595]: info: Asound.conf file unchanged, so no further update is needed Feb 09 07:51:46 music volumio[21595]: info: Output device has changed, restarting MPD Feb 09 07:51:46 music volumio[21595]: info: Output device has changed, restarting Shairport Sync Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:46 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:46 music sudo[21719]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:46 music volumio[21595]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:46 music volumio[21595]: info: ___________ START PLUGINS ___________ Feb 09 07:51:47 music sudo[21719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:47 music sudo[21721]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:47 music sudo[21719]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:47 music volumio[21595]: info: ControllerMpd::onStart: Initializing MPD Feb 09 07:51:47 music volumio[21595]: info: Creating MPD Configuration file Feb 09 07:51:47 music sudo[21721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:51:47 music sudo[21728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:51:47 music sudo[21728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:47 music volumio[21595]: info: [1770641507060] CoreMusicLibrary::Adding element Media Servers Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:47 music sudo[21728]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:47 music sudo[21731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:51:47 music sudo[21731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:47 music volumio[21595]: info: UPNP Browser: Client initialized successfully Feb 09 07:51:47 music systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 09 07:51:47 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:51:47 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:51:47 music systemd[1]: mpd.service: Consumed 4.151s CPU time. Feb 09 07:51:47 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 09 07:51:47 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:51:47 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:51:47 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:47 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:51:47 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:47 music volumio[21595]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:47 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:47 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:51:47 music go-librespot[21742]: go-librespot daemon starting... Feb 09 07:51:47 music volumio[21595]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=debug msg="app state loaded" Feb 09 07:51:47 music volumio[21595]: info: [1770641507349] CoreMusicLibrary::Adding element Last_100 Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:51:47 music volumio[21595]: info: [1770641507360] CoreMusicLibrary::Adding element Webradio Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:47 music volumio[21595]: info: Initializing BBC Radios Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:47 music volumio[21595]: info: Creating Spotify config file Feb 09 07:51:47 music sudo[21745]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 09 07:51:47 music sudo[21745]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 09 07:51:47 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:47 music sudo[21745]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:47 music go-librespot[21746]: time="2026-02-09T07:51:47-05:00" level=info msg="zeroconf server listening on port 45673" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="obtained new client token: AAAosAxbWHi0QlbcKs0INJli9pdUkWzZMxf2qc93BgAAjJSAjH6/Eh7xBBlChKUgf8dNF71ef30oR9YO1wM7VxFDTeapieTpdeD6S4Mszcufad4MCgK1EHwuC9Unc2V2luvxpgf8thM0/nQcsfSGPOsB3ol0uBIIihlLxCYgSTuOSBKw645uaxpJ2qQ2SiYA9ZbeIBhOoiKERFXhwOtrAQv3QLI2dghXOQSjB70El8xkkpFC8VVDx90=" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="completed challenge" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:48 music volumio[21681]: Starting albumart workers Feb 09 07:51:48 music volumio[21595]: info: Volumio Calling Home Feb 09 07:51:48 music volumio[21682]: Starting albumart workers Feb 09 07:51:48 music volumio[21680]: Starting albumart workers Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=debug msg="completed challenge" Feb 09 07:51:48 music go-librespot[21746]: time="2026-02-09T07:51:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:49 music volumio[21595]: info: MPD Permissions set Feb 09 07:51:49 music volumio[21595]: info: MPD Permissions set Feb 09 07:51:49 music volumio[21595]: info: Volumio called home Feb 09 07:51:49 music volumio[21595]: info: Spotify config file written Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:49 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:49 music sudo[21774]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 07:51:49 music sudo[21774]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:49 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 07:51:49 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 07:51:49 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:49 music volumio[21595]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:49 music go-librespot[21777]: go-librespot daemon starting... Feb 09 07:51:49 music sudo[21774]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music go-librespot[21783]: time="2026-02-09T07:51:49-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:49 music go-librespot[21783]: time="2026-02-09T07:51:49-05:00" level=debug msg="app state loaded" Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:51:49 music volumio[21595]: info: No need to fix Spotify hosts Feb 09 07:51:49 music go-librespot[21783]: time="2026-02-09T07:51:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:49 music volumio[21595]: info: Listing playlists Feb 09 07:51:49 music volumio[21595]: info: Listing playlists Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=info msg="zeroconf server listening on port 39365" Feb 09 07:51:50 music volumio[21595]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 09 07:51:50 music volumio[21595]: info: Starting Shairport Sync Feb 09 07:51:50 music volumio[21595]: info: Starting Shairport Sync Feb 09 07:51:50 music volumio[21595]: info: Starting Shairport Sync Feb 09 07:51:50 music sudo[21816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:50 music sudo[21816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:50 music sudo[21818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:50 music sudo[21818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:50 music sudo[21820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:51:50 music sudo[21820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="obtained new client token: AABR56TXLvYeWAZzzs8m6qL12xBqZcluxPSuWUzaLxX4OHQ5Tc08w++gNgkdFLyckWyUOIOI5YfrT0Kwl1KsLVprron251D8ZtcB/3sCll8ht3oerUpptZ0jvkIyLLJ4RPLJwyHljBoI43vsEzsCDTY9UU/WPtdKBWSC64SylN8ll/9gg6JjVzHUy4x/DYx9xUW+2c2CntaNhw2fzRHkJeV6792H9uUFz48Ed7lZxpVSDFOr8qgi" Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Feb 09 07:51:50 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:50 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:50 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:51:50 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:51:50 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:50 music systemd[1]: shairport-sync.service: Consumed 1.837s CPU time. Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:50 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:51:50 music sudo[21820]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:50 music sudo[21816]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:50 music sudo[21818]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:50 music volumio[21595]: info: Shairport-Sync Started Feb 09 07:51:50 music volumio[21595]: Error adding Membership: Error: addMembership EINVAL Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=debug msg="completed challenge" Feb 09 07:51:50 music volumio[21595]: info: Shairport-Sync Started Feb 09 07:51:50 music volumio[21595]: info: Shairport-Sync Started Feb 09 07:51:50 music go-librespot[21783]: time="2026-02-09T07:51:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="completed challenge" Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:51 music mpd[21768]: 2026-02-09T07:51:51 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:51:51 music systemd[1]: Started mpd.service - Music Player Daemon. Feb 09 07:51:51 music sudo[21731]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:51 music sudo[21721]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:51 music volumio[21595]: info: Completed starting Core Plugins Feb 09 07:51:51 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:51 music volumio[21595]: info: ----- MyVolumio plugins startup ---- Feb 09 07:51:51 music volumio[21595]: info: ------------------------------------------- Feb 09 07:51:51 music volumio[21595]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=debug msg="completed challenge" Feb 09 07:51:51 music go-librespot[21783]: time="2026-02-09T07:51:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:51 music volumio[21595]: error: MPD error: The expression evaluated to a falsy value: Feb 09 07:51:51 music volumio[21595]: assert.ok(self.idling) Feb 09 07:51:51 music volumio[21595]: error: The expression evaluated to a falsy value: Feb 09 07:51:51 music volumio[21595]: assert.ok(self.idling) Feb 09 07:51:51 music volumio[21595]: info: MPD running with PID21768 Feb 09 07:51:51 music volumio[21595]: ,establishing connection Feb 09 07:51:51 music volumio[21595]: error: updateQueue error: null Feb 09 07:51:51 music volumio[21595]: error: updateQueue error: null Feb 09 07:51:52 music go-librespot[21783]: time="2026-02-09T07:51:52-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:51:52 music sudo[21859]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:51:52 music sudo[21859]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:52 music sudo[21861]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:51:52 music sudo[21859]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:52 music sudo[21861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:52 music sudo[21861]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:52 music sudo[21865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 09 07:51:52 music sudo[21865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:52 music sudo[21865]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:52 music volumio[21595]: info: Upmpdcli Daemon Started Feb 09 07:51:52 music go-librespot[21783]: time="2026-02-09T07:51:52-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:52 music go-librespot[21783]: time="2026-02-09T07:51:52-05:00" level=debug msg="completed challenge" Feb 09 07:51:52 music go-librespot[21783]: time="2026-02-09T07:51:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:53 music volumio[21595]: info: go-librespot daemon successfully initialized Feb 09 07:51:53 music go-librespot[21783]: time="2026-02-09T07:51:53-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:51:53 music go-librespot[21783]: time="2026-02-09T07:51:53-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:53 music go-librespot[21783]: time="2026-02-09T07:51:53-05:00" level=debug msg="completed challenge" Feb 09 07:51:53 music go-librespot[21783]: time="2026-02-09T07:51:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:54 music go-librespot[21783]: time="2026-02-09T07:51:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:54 music go-librespot[21783]: time="2026-02-09T07:51:54-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:54 music go-librespot[21783]: time="2026-02-09T07:51:54-05:00" level=debug msg="completed challenge" Feb 09 07:51:54 music go-librespot[21783]: time="2026-02-09T07:51:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:54 music go-librespot[21783]: time="2026-02-09T07:51:54-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:54 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:51:54 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:51:54 music sudo[21871]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:54 music sudo[21871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:54 music sudo[21874]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:51:54 music sudo[21874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:51:54 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:51:54 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:51:54 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:54 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:54 music mpd_monitor.sh[21876]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:51:54 music sudo[21871]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:54 music volumio[21595]: info: Successfully started MPD Monitor Feb 09 07:51:54 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:51:54 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:51:54 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:54 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:51:54 music mpd_monitor.sh[21881]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:51:54 music sudo[21874]: pam_unix(sudo:session): session closed for user root Feb 09 07:51:54 music volumio[21595]: info: Successfully started MPD Monitor Feb 09 07:51:56 music volumio[21595]: info: Initializing connection to go-librespot Websocket Feb 09 07:51:56 music volumio[21595]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:51:56 music volumio[21595]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 09 07:51:57 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 09 07:51:57 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:57 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:51:57 music go-librespot[21885]: go-librespot daemon starting... Feb 09 07:51:57 music go-librespot[21886]: time="2026-02-09T07:51:57-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:51:57 music go-librespot[21886]: time="2026-02-09T07:51:57-05:00" level=debug msg="app state loaded" Feb 09 07:51:57 music go-librespot[21886]: time="2026-02-09T07:51:57-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=info msg="zeroconf server listening on port 41583" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="obtained new client token: AACgrFdYLeCCnGT9pdDu/p1I5UGhPUste6YdZ3AIVifaJq/v3Bhq8kqRsTItPG6TSmOnOvzM7SAscc5y+vfIMUOLtiJAfu2KJSUnylhhckDaC7CfbzI7jeG+riThUi1XLIES8BC4aYoL43bQPiKkGEUENCP64JemkVoJijP/dpt3SnthC7rV6Tt6imbPM6zdy/OYvkR4cpyMUT57ruVlCZMI4wBdd6yaX+JRlwM/FZHdtEwWuDaQjHA=" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=debug msg="completed challenge" Feb 09 07:51:58 music go-librespot[21886]: time="2026-02-09T07:51:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:58 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:51:58 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:51:59 music volumio[21595]: info: Initializing connection to go-librespot Websocket Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="new websocket client" Feb 09 07:51:59 music volumio[21595]: info: Connection to go-librespot Websocket established Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="completed challenge" Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="completed keyexchange" Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=debug msg="completed challenge" Feb 09 07:51:59 music go-librespot[21886]: time="2026-02-09T07:51:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 09 07:52:00 music volumio[21595]: info: Adding plugin bluetooth to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin multiroom to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin metavolumio to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin cd_controller to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 09 07:52:00 music volumio[21595]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 09 07:52:00 music go-librespot[21886]: time="2026-02-09T07:52:00-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:00 music go-librespot[21886]: time="2026-02-09T07:52:00-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:00 music go-librespot[21886]: time="2026-02-09T07:52:00-05:00" level=debug msg="completed challenge" Feb 09 07:52:00 music go-librespot[21886]: time="2026-02-09T07:52:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:01 music volumio[21595]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 09 07:52:01 music volumio[21595]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 09 07:52:01 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:01 music volumio[21595]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:01 music volumio[21595]: info: Starting MyVolumio Remote Streaming Endpoints Feb 09 07:52:01 music volumio[21595]: info: MyVolumio login type: Token Feb 09 07:52:01 music volumio[21595]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 09 07:52:01 music volumio[21595]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 09 07:52:01 music go-librespot[21886]: time="2026-02-09T07:52:01-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:52:01 music go-librespot[21886]: time="2026-02-09T07:52:01-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:01 music go-librespot[21886]: time="2026-02-09T07:52:01-05:00" level=debug msg="completed challenge" Feb 09 07:52:01 music go-librespot[21886]: time="2026-02-09T07:52:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:02 music volumio[21595]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 09 07:52:02 music volumio[21595]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 09 07:52:02 music volumio[21595]: info: Streaming services startup Feb 09 07:52:02 music volumio[21595]: info: Starting Streaming Daemon Feb 09 07:52:02 music sudo[21896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 09 07:52:02 music sudo[21896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:02 music volumio[21595]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 09 07:52:02 music sudo[21896]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:02 music volumio[21595]: info: Getting Spotify volume Feb 09 07:52:02 music volumio[21595]: error: Cannot start Volumio Streaming Daemon Feb 09 07:52:02 music volumio[21595]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 09 07:52:02 music volumio[21595]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 09 07:52:02 music volumio[21595]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Feb 09 07:52:02 music go-librespot[21886]: time="2026-02-09T07:52:02-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:52:02 music go-librespot[21886]: time="2026-02-09T07:52:02-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:02 music go-librespot[21886]: time="2026-02-09T07:52:02-05:00" level=debug msg="completed challenge" Feb 09 07:52:02 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:02 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:02 music volumio[21595]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 09 07:52:02 music volumio[21595]: SPOTIFY: SPOTIFY VOLUME undefined Feb 09 07:52:02 music volumio[21595]: SPOTIFY: VOLUMIO VOLUME 86 Feb 09 07:52:02 music volumio[21595]: info: Aligning Spotify Volume to Volumio Volume Feb 09 07:52:02 music volumio[21595]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:02 music volumio[21595]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:02 music volumio[21595]: info: Setting Spotify Volume from Volumio: 86 Feb 09 07:52:02 music go-librespot[21886]: time="2026-02-09T07:52:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:02 music go-librespot[21886]: time="2026-02-09T07:52:02-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:02 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:02 music volumio[21595]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:02 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:02 music volumio[21595]: Error: socket hang up Feb 09 07:52:02 music volumio[21595]: at connResetException (node:internal/errors:720:14) Feb 09 07:52:02 music volumio[21595]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 09 07:52:02 music volumio[21595]: at Socket.emit (node:events:526:35) Feb 09 07:52:02 music volumio[21595]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 09 07:52:02 music volumio[21595]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 09 07:52:02 music volumio[21595]: code: 'ECONNRESET', Feb 09 07:52:02 music volumio[21595]: response: undefined Feb 09 07:52:02 music volumio[21595]: } Feb 09 07:52:02 music volumio[21595]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:03 music sudo[21931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 07:51' Feb 09 07:52:03 music sudo[21931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:03 music sudo[21931]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:04 music volumio-remote-updater[30265]: [2026-02-09 07:52:04] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 09 07:52:04 music volumio-remote-updater[30265]: [2026-02-09 07:52:04] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 09 07:52:04 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:04 music systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 09 07:52:04 music systemd[1]: volumio.service: Consumed 26.824s CPU time. Feb 09 07:52:04 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:52:04 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:52:04 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 52540. Feb 09 07:52:04 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:52:04 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 09 07:52:04 music systemd[1]: volumio.service: Consumed 26.824s CPU time. Feb 09 07:52:04 music systemd[1]: Started volumio.service - Volumio Backend Module. Feb 09 07:52:04 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:52:05 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Feb 09 07:52:05 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:05 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:05 music go-librespot[21961]: go-librespot daemon starting... Feb 09 07:52:05 music go-librespot[21962]: time="2026-02-09T07:52:05-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:05 music go-librespot[21962]: time="2026-02-09T07:52:05-05:00" level=debug msg="app state loaded" Feb 09 07:52:05 music go-librespot[21962]: time="2026-02-09T07:52:05-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=info msg="zeroconf server listening on port 34787" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="obtained new client token: AADoDarxcbACFFC3y66sLERamncNqD+M7ksi/3YjxVBVNaRcQYvFRkiDig64+cIXSZ0lF0l/sWWeM4UUZ4FDoEy3mfhtQ2V1K1otYSex/+JOF7HU94E7Owz3G/0lv2tAEN87U1s7YR5gBaTIE/gXVgX4I9P5HOseoT0rIz7l/RojfJxfRwb0bMVohp/PWJhGoSikua7q1KhsPOlQFEWx8Er1NI42RmgrKrmhIzHiguL4WnN+GzGU+lw=" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=debug msg="completed challenge" Feb 09 07:52:06 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:06 music volumio[21946]: info: ----- Volumio3 ---- Feb 09 07:52:06 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:06 music volumio[21946]: info: ----- System startup ---- Feb 09 07:52:06 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:06 music go-librespot[21962]: time="2026-02-09T07:52:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:07 music go-librespot[21962]: time="2026-02-09T07:52:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:52:07 music go-librespot[21962]: time="2026-02-09T07:52:07-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:07 music go-librespot[21962]: time="2026-02-09T07:52:07-05:00" level=debug msg="completed challenge" Feb 09 07:52:07 music go-librespot[21962]: time="2026-02-09T07:52:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:07 music volumio[21946]: info: MYVOLUMIO Environment detected Feb 09 07:52:07 music volumio[21946]: info: Plugin folders cleanup Feb 09 07:52:07 music volumio[21946]: info: Scanning into folder /volumio/app/plugins/ Feb 09 07:52:07 music volumio[21946]: info: Scanning category audio_interface Feb 09 07:52:07 music volumio[21946]: info: Scanning category miscellanea Feb 09 07:52:07 music volumio[21946]: info: Scanning category music_service Feb 09 07:52:07 music volumio[21946]: info: Scanning category plugins.json Feb 09 07:52:07 music volumio[21946]: info: Scanning category system_controller Feb 09 07:52:07 music volumio[21946]: info: Scanning category user_interface Feb 09 07:52:07 music volumio[21946]: info: Scanning into folder /data/plugins/ Feb 09 07:52:07 music volumio[21946]: info: Scanning category music_service Feb 09 07:52:07 music volumio[21946]: info: Plugin folders cleanup completed Feb 09 07:52:07 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:07 music volumio[21946]: info: ----- Core plugins startup ---- Feb 09 07:52:07 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:07 music volumio[21946]: info: Loading plugins from folder /volumio/app/plugins/ Feb 09 07:52:07 music volumio[21946]: info: Adding plugin upnp to MyMusic Plugins Feb 09 07:52:07 music volumio[21946]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 09 07:52:07 music volumio[21946]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 09 07:52:07 music volumio[21946]: info: Loading plugins from folder /data/plugins/ Feb 09 07:52:07 music volumio[21946]: info: Loading plugin "system"... Feb 09 07:52:07 music volumio[21946]: info: Loading plugin "appearance"... Feb 09 07:52:07 music go-librespot[21962]: time="2026-02-09T07:52:07-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.255.62:80: connect: connection refused" Feb 09 07:52:08 music go-librespot[21962]: time="2026-02-09T07:52:08-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Feb 09 07:52:08 music go-librespot[21962]: time="2026-02-09T07:52:08-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:08 music go-librespot[21962]: time="2026-02-09T07:52:08-05:00" level=debug msg="completed challenge" Feb 09 07:52:08 music go-librespot[21962]: time="2026-02-09T07:52:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "network"... Feb 09 07:52:08 music volumio[21946]: info: Refreshing Cached IP Addresses Feb 09 07:52:08 music sudo[21984]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:52:08 music sudo[21984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:08 music sudo[21984]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:08 music sudo[21986]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "services"... Feb 09 07:52:08 music sudo[21986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "alsa_controller"... Feb 09 07:52:08 music sudo[21986]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:08 music sudo[21994]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 09 07:52:08 music sudo[21994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:08 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "wizard"... Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "networkfs"... Feb 09 07:52:08 music volumio[21946]: info: Starting Udev Watcher for removable devices Feb 09 07:52:08 music volumio[21946]: info: Ignoring mount for partition: boot Feb 09 07:52:08 music volumio[21946]: info: Ignoring mount for partition: volumio Feb 09 07:52:08 music volumio[21946]: info: Ignoring mount for partition: volumio_data Feb 09 07:52:08 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "volumio_command_line_client"... Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "upnp"... Feb 09 07:52:08 music volumio[21946]: info: [1770641528823] Starting Upmpd Daemon Feb 09 07:52:08 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "my_music"... Feb 09 07:52:08 music volumio[21946]: info: Loading plugin "mpd"... Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 09 07:52:09 music volumio[21946]: info: Loading plugin "upnp_browser"... Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:40988->104.199.65.9:443: read: connection reset by peer" Feb 09 07:52:09 music sudo[21994]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:09 music volumio-remote-updater[30265]: [2026-02-09 07:52:09] [connect] Successful connection Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:09 music go-librespot[21962]: time="2026-02-09T07:52:09-05:00" level=debug msg="completed challenge" Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:10 music volumio[21946]: info: Starting UPNP Browser Feb 09 07:52:10 music volumio[21946]: info: Loading plugin "alarm-clock"... Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=debug msg="completed challenge" Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:10 music go-librespot[21962]: time="2026-02-09T07:52:10-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:10 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:10 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:10 music volumio[21946]: info: Loading plugin "airplay_emulation"... Feb 09 07:52:10 music volumio[21946]: info: Starting Shairport Sync Feb 09 07:52:10 music volumio[21946]: info: Loading plugin "last_100"... Feb 09 07:52:10 music volumio[21946]: info: Loading plugin "webradio"... Feb 09 07:52:11 music volumio[21946]: info: Loading plugin "i2s_dacs"... Feb 09 07:52:11 music volumio[21946]: info: I2S DAC not set, start Auto-detection Feb 09 07:52:11 music volumio[21946]: info: Loading plugin "volumiodiscovery"... Feb 09 07:52:11 music volumio[21946]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:11 music volumio[21946]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:11 music volumio[21946]: *** WARNING *** For more information see Feb 09 07:52:11 music volumio[21946]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:11 music volumio[21946]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:11 music volumio[21946]: *** WARNING *** For more information see Feb 09 07:52:11 music node[21946]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:11 music node[21946]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:11 music node[21946]: *** WARNING *** For more information see Feb 09 07:52:11 music node[21946]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:11 music node[21946]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:11 music node[21946]: *** WARNING *** For more information see Feb 09 07:52:11 music volumio[21946]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 09 07:52:11 music volumio[21946]: info: Discovery: Started advertising with name: music Feb 09 07:52:11 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:11 music volumio[21946]: info: Loading plugin "spop"... Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "outputs"... Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "albumart"... Feb 09 07:52:12 music volumio[21946]: info: Plugin example_plugin is not enabled Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "inputs"... Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "updater_comm"... Feb 09 07:52:12 music volumio[21946]: info: Plugin mpdemulation is not enabled Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "rest_api"... Feb 09 07:52:12 music volumio[21946]: info: Loading plugin "websocket"... Feb 09 07:52:12 music volumio[21946]: info: Starting Socket.io Server version 1.7.4 Feb 09 07:52:12 music volumio[21946]: info: Loading i18n strings for locale en Feb 09 07:52:12 music volumio[21946]: Updating browse sources language Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::initPlayerControls Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:12 music volumio[21946]: Express server listening on port 3000 Feb 09 07:52:12 music volumio[21946]: [Metrics] WebUI: 6s 561.59ms Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::resetVolumioState Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::getcurrentVolume Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:12 music volumio[21946]: info: Volumio Network Manager: Network status updated: 1 Feb 09 07:52:12 music volumio[21946]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::pushState Feb 09 07:52:12 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::updateTrackBlock Feb 09 07:52:12 music volumio[22019]: Forking 3 albumart workers Feb 09 07:52:12 music volumio[21946]: info: CorePlayQueue::getTrackBlock Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:12 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:12 music volumio-remote-updater[30265]: [2026-02-09 07:52:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770641529 101 Feb 09 07:52:12 music volumio[21946]: 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 Feb 09 07:52:12 music volumio[21946]: info: Reloading queue from file Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::setRepeat null single undefined Feb 09 07:52:12 music volumio[21946]: info: CoreStateMachine::pushState Feb 09 07:52:12 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:52:12 music volumio[21946]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:13 music volumio[21946]: info: CoreStateMachine::setRandom null Feb 09 07:52:13 music volumio[21946]: info: CoreStateMachine::pushState Feb 09 07:52:13 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:13 music volumio[21946]: info: Setting Device type: Raspberry PI Feb 09 07:52:13 music volumio[21946]: info: Listing playlists Feb 09 07:52:13 music volumio[21946]: info: Listing playlists Feb 09 07:52:13 music volumio[21946]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:52:13 music volumio[21946]: info: CoreStateMachine::pushState Feb 09 07:52:13 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:13 music volumio[21946]: info: Completed loading Core Plugins Feb 09 07:52:13 music volumio[21946]: info: Preparing to generate the ALSA configuration file Feb 09 07:52:13 music volumio[21946]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:52:13 music volumio[21946]: info: Discovery: Found device music Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:13 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:13 music volumio[21946]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:52:13 music volumio[21946]: info: Discovery: Found device music Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:13 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:13 music volumio[21946]: info: Asound.conf file unchanged, so no further update is needed Feb 09 07:52:13 music volumio[21946]: info: Output device has changed, restarting MPD Feb 09 07:52:13 music volumio[21946]: info: Output device has changed, restarting Shairport Sync Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:13 music sudo[22074]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:52:13 music sudo[22074]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:13 music sudo[22076]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:52:13 music sudo[22076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:13 music volumio[21946]: info: ___________ START PLUGINS ___________ Feb 09 07:52:13 music volumio[21946]: info: ControllerMpd::onStart: Initializing MPD Feb 09 07:52:13 music volumio[21946]: info: Creating MPD Configuration file Feb 09 07:52:13 music sudo[22074]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:13 music systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:13 music volumio[21946]: info: [1770641533352] CoreMusicLibrary::Adding element Media Servers Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:13 music sudo[22084]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:52:13 music sudo[22084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:13 music sudo[22084]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:13 music volumio[21946]: info: UPNP Browser: Client initialized successfully Feb 09 07:52:13 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:52:13 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:52:13 music systemd[1]: mpd.service: Consumed 4.220s CPU time. Feb 09 07:52:13 music sudo[22086]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:52:13 music sudo[22086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:13 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:52:13 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:52:13 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:13 music volumio[21946]: info: [1770641533508] CoreMusicLibrary::Adding element Last_100 Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:13 music volumio[21946]: info: [1770641533514] CoreMusicLibrary::Adding element Webradio Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:13 music volumio[21946]: info: Initializing BBC Radios Feb 09 07:52:13 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:52:13 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:52:13 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:52:13 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:52:13 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:52:13 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:52:13 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:52:13 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:13 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:13 music volumio[21946]: info: Creating Spotify config file Feb 09 07:52:13 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:13 music sudo[22113]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 09 07:52:13 music sudo[22113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 09 07:52:13 music sudo[22113]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:13 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 09 07:52:13 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:14 music go-librespot[22115]: go-librespot daemon starting... Feb 09 07:52:14 music go-librespot[22116]: time="2026-02-09T07:52:14-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:14 music volumio[21946]: info: Volumio Calling Home Feb 09 07:52:14 music go-librespot[22116]: time="2026-02-09T07:52:14-05:00" level=info msg="zeroconf server listening on port 43689" Feb 09 07:52:14 music volumio[21946]: info: MPD Permissions set Feb 09 07:52:14 music volumio[21946]: info: MPD Permissions set Feb 09 07:52:14 music volumio[21946]: info: Spotify config file written Feb 09 07:52:14 music volumio[21946]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[22036]: Starting albumart workers Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music sudo[22130]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music sudo[22130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:14 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:14 music systemd[1]: go-librespot-daemon.service: Killing process 22119 (go-librespot) with signal SIGKILL. Feb 09 07:52:14 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 07:52:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:14 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:14 music volumio[21946]: info: No need to fix Spotify hosts Feb 09 07:52:15 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:15 music sudo[22130]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:15 music go-librespot[22144]: go-librespot daemon starting... Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="app state loaded" Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:15 music volumio[22038]: Starting albumart workers Feb 09 07:52:15 music volumio[22037]: Starting albumart workers Feb 09 07:52:15 music volumio[21946]: info: Volumio called home Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=info msg="zeroconf server listening on port 35111" Feb 09 07:52:15 music volumio[21946]: info: Starting Shairport Sync Feb 09 07:52:15 music volumio[21946]: info: Starting Shairport Sync Feb 09 07:52:15 music volumio[21946]: info: Starting Shairport Sync Feb 09 07:52:15 music volumio[21946]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 09 07:52:15 music sudo[22155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:15 music sudo[22155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="obtained new client token: AAD1m7eMhUBN7HKM1B/sAkYAOYcjEMfBLmOvgHDHp6xW/FsOl4QknMKab2kiFf6dpkeNgKroan9mA7yiS1w6yYs+PpyhRA/2Sscusvz0BMjkylgg32+65hJssVoVMl5fS/wnBNxPLBZcsY1T4akucO3jEGBKXLcPaQiILeT9PCAH5IVIepFempvxWbazyigUkTkzF7jIZfQei2I++RUp4He9sx63iTXH+YIqME2G78uFux7xeKY/Ukg=" Feb 09 07:52:15 music sudo[22157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:15 music sudo[22157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:15 music sudo[22159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:15 music sudo[22159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:15 music go-librespot[22145]: time="2026-02-09T07:52:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:15 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:52:15 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:52:15 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:15 music systemd[1]: shairport-sync.service: Consumed 1.875s CPU time. Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=debug msg="completed challenge" Feb 09 07:52:16 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:16 music sudo[22155]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:16 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:52:16 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:52:16 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:16 music volumio[21946]: info: Shairport-Sync Started Feb 09 07:52:16 music volumio[21946]: Error adding Membership: Error: addMembership EINVAL Feb 09 07:52:16 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:16 music sudo[22159]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:16 music sudo[22157]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:16 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:16 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:16 music volumio[21946]: info: Shairport-Sync Started Feb 09 07:52:16 music volumio[21946]: info: Shairport-Sync Started Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=debug msg="completed challenge" Feb 09 07:52:16 music go-librespot[22145]: time="2026-02-09T07:52:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:17 music go-librespot[22145]: time="2026-02-09T07:52:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:17 music go-librespot[22145]: time="2026-02-09T07:52:17-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:17 music go-librespot[22145]: time="2026-02-09T07:52:17-05:00" level=debug msg="completed challenge" Feb 09 07:52:17 music go-librespot[22145]: time="2026-02-09T07:52:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:18 music go-librespot[22145]: time="2026-02-09T07:52:18-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:18 music go-librespot[22145]: time="2026-02-09T07:52:18-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:18 music go-librespot[22145]: time="2026-02-09T07:52:18-05:00" level=debug msg="completed challenge" Feb 09 07:52:18 music mpd[22117]: 2026-02-09T07:52:18 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 09 07:52:18 music systemd[1]: Started mpd.service - Music Player Daemon. Feb 09 07:52:18 music sudo[22076]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:18 music sudo[22086]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:18 music go-librespot[22145]: time="2026-02-09T07:52:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:18 music volumio[21946]: info: Completed starting Core Plugins Feb 09 07:52:18 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:18 music volumio[21946]: info: ----- MyVolumio plugins startup ---- Feb 09 07:52:18 music volumio[21946]: info: ------------------------------------------- Feb 09 07:52:18 music volumio[21946]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 09 07:52:18 music volumio[21946]: error: MPD error: The expression evaluated to a falsy value: Feb 09 07:52:18 music volumio[21946]: assert.ok(self.idling) Feb 09 07:52:18 music volumio[21946]: error: The expression evaluated to a falsy value: Feb 09 07:52:18 music volumio[21946]: assert.ok(self.idling) Feb 09 07:52:18 music volumio[21946]: error: updateQueue error: null Feb 09 07:52:18 music volumio[21946]: info: MPD running with PID22117 Feb 09 07:52:18 music volumio[21946]: ,establishing connection Feb 09 07:52:18 music volumio[21946]: error: updateQueue error: null Feb 09 07:52:18 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:18 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:18 music volumio[21946]: info: go-librespot daemon successfully initialized Feb 09 07:52:18 music sudo[22218]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:52:18 music sudo[22218]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:18 music go-librespot[22145]: time="2026-02-09T07:52:18-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:52:18 music sudo[22218]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:18 music sudo[22220]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:52:18 music sudo[22220]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:18 music sudo[22220]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:18 music sudo[22223]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 09 07:52:18 music sudo[22223]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:18 music sudo[22223]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:18 music volumio[21946]: info: Upmpdcli Daemon Started Feb 09 07:52:19 music go-librespot[22145]: time="2026-02-09T07:52:19-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:19 music go-librespot[22145]: time="2026-02-09T07:52:19-05:00" level=debug msg="completed challenge" Feb 09 07:52:19 music go-librespot[22145]: time="2026-02-09T07:52:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:19 music go-librespot[22145]: time="2026-02-09T07:52:19-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 09 07:52:20 music go-librespot[22145]: time="2026-02-09T07:52:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 09 07:52:20 music go-librespot[22145]: time="2026-02-09T07:52:20-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 09 07:52:20 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:20 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:21 music sudo[22227]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:52:21 music sudo[22227]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:21 music sudo[22229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:52:21 music sudo[22229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:21 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:52:21 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:52:21 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:21 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:21 music sudo[22227]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:21 music sudo[22229]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:21 music mpd_monitor.sh[22232]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:52:21 music volumio[21946]: info: Successfully started MPD Monitor Feb 09 07:52:21 music volumio[21946]: info: Successfully started MPD Monitor Feb 09 07:52:21 music volumio[21946]: info: Initializing connection to go-librespot Websocket Feb 09 07:52:21 music volumio[21946]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:52:23 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 09 07:52:23 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:23 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:23 music go-librespot[22236]: go-librespot daemon starting... Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="app state loaded" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:23 music volumio[21946]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=info msg="zeroconf server listening on port 33885" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="obtained new client token: AAA5X3e8Brp6M3wWDNsmteqbSdMRcwWo92P+0hPRQ7qMc6pIaV+r9/jjp3ogT0YKgkLiBVlwaRX2jNcxjZ28kvz8LpTGDWutpjbQSiUcKRU+d8zpI8gcpINLblhw7LTCt2ZRFhry5w1YmOL2vIRR6Y4GRX5h242hU857aAcotVIRAqey0P75EVHPMyLD8HGyA2EA8DbcNRN33DcskWzsFt2AD7tQjzCiRYfnoc458NMBHg/4wJpMuqs=" Feb 09 07:52:23 music go-librespot[22237]: time="2026-02-09T07:52:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:24 music go-librespot[22237]: time="2026-02-09T07:52:24-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:24 music go-librespot[22237]: time="2026-02-09T07:52:24-05:00" level=debug msg="completed challenge" Feb 09 07:52:24 music go-librespot[22237]: time="2026-02-09T07:52:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:24 music volumio[21946]: info: Initializing connection to go-librespot Websocket Feb 09 07:52:24 music go-librespot[22237]: time="2026-02-09T07:52:24-05:00" level=debug msg="new websocket client" Feb 09 07:52:24 music volumio[21946]: info: Connection to go-librespot Websocket established Feb 09 07:52:25 music go-librespot[22237]: time="2026-02-09T07:52:25-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Feb 09 07:52:25 music go-librespot[22237]: time="2026-02-09T07:52:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:25 music go-librespot[22237]: time="2026-02-09T07:52:25-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:25 music go-librespot[22237]: time="2026-02-09T07:52:25-05:00" level=debug msg="completed challenge" Feb 09 07:52:25 music go-librespot[22237]: time="2026-02-09T07:52:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 09 07:52:26 music volumio[21946]: info: Adding plugin bluetooth to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin multiroom to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin metavolumio to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin cd_controller to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 09 07:52:26 music volumio[21946]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 09 07:52:26 music go-librespot[22237]: time="2026-02-09T07:52:26-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:26 music go-librespot[22237]: time="2026-02-09T07:52:26-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:26 music go-librespot[22237]: time="2026-02-09T07:52:26-05:00" level=debug msg="completed challenge" Feb 09 07:52:26 music go-librespot[22237]: time="2026-02-09T07:52:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:27 music go-librespot[22237]: time="2026-02-09T07:52:27-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:52:27 music volumio[21946]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 09 07:52:27 music volumio[21946]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 09 07:52:27 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:27 music volumio[21946]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:27 music volumio[21946]: info: Starting MyVolumio Remote Streaming Endpoints Feb 09 07:52:27 music go-librespot[22237]: time="2026-02-09T07:52:27-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:27 music go-librespot[22237]: time="2026-02-09T07:52:27-05:00" level=debug msg="completed challenge" Feb 09 07:52:27 music volumio[21946]: info: MyVolumio login type: Token Feb 09 07:52:27 music volumio[21946]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 09 07:52:27 music volumio[21946]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 09 07:52:27 music go-librespot[22237]: time="2026-02-09T07:52:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:28 music go-librespot[22237]: time="2026-02-09T07:52:28-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 09 07:52:28 music volumio[21946]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 09 07:52:28 music volumio[21946]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 09 07:52:28 music volumio[21946]: info: Streaming services startup Feb 09 07:52:28 music volumio[21946]: info: Starting Streaming Daemon Feb 09 07:52:28 music sudo[22247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 09 07:52:28 music sudo[22247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:28 music volumio[21946]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 09 07:52:28 music go-librespot[22237]: time="2026-02-09T07:52:28-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:28 music go-librespot[22237]: time="2026-02-09T07:52:28-05:00" level=debug msg="completed challenge" Feb 09 07:52:28 music sudo[22247]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:28 music volumio[21946]: info: Getting Spotify volume Feb 09 07:52:28 music volumio[21946]: error: Cannot start Volumio Streaming Daemon Feb 09 07:52:28 music volumio[21946]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 09 07:52:28 music volumio[21946]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 09 07:52:28 music volumio[21946]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Feb 09 07:52:28 music go-librespot[22237]: time="2026-02-09T07:52:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:28 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:28 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:28 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:28 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:28 music volumio[21946]: info: Listing playlists Feb 09 07:52:28 music volumio[21946]: info: Listing playlists Feb 09 07:52:28 music volumio[21946]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Feb 09 07:52:28 music volumio[21946]: SPOTIFY: SPOTIFY VOLUME undefined Feb 09 07:52:28 music volumio[21946]: SPOTIFY: VOLUMIO VOLUME 86 Feb 09 07:52:28 music volumio[21946]: info: Aligning Spotify Volume to Volumio Volume Feb 09 07:52:28 music volumio[21946]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:28 music volumio[21946]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:28 music volumio[21946]: info: Setting Spotify Volume from Volumio: 86 Feb 09 07:52:28 music volumio[21946]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 09 07:52:29 music go-librespot[22237]: time="2026-02-09T07:52:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:29 music go-librespot[22237]: time="2026-02-09T07:52:29-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:29 music go-librespot[22237]: time="2026-02-09T07:52:29-05:00" level=debug msg="completed challenge" Feb 09 07:52:29 music go-librespot[22237]: time="2026-02-09T07:52:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:29 music go-librespot[22237]: time="2026-02-09T07:52:29-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:29 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:29 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:29 music volumio[21946]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:29 music volumio[21946]: Error: socket hang up Feb 09 07:52:29 music volumio[21946]: at connResetException (node:internal/errors:720:14) Feb 09 07:52:29 music volumio[21946]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 09 07:52:29 music volumio[21946]: at Socket.emit (node:events:526:35) Feb 09 07:52:29 music volumio[21946]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 09 07:52:29 music volumio[21946]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 09 07:52:29 music volumio[21946]: code: 'ECONNRESET', Feb 09 07:52:29 music volumio[21946]: response: undefined Feb 09 07:52:29 music volumio[21946]: } Feb 09 07:52:29 music volumio[21946]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:30 music sudo[22282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 07:51' Feb 09 07:52:30 music sudo[22282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:30 music sudo[22282]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:30 music volumio-remote-updater[30265]: [2026-02-09 07:52:30] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 09 07:52:30 music volumio-remote-updater[30265]: [2026-02-09 07:52:30] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 09 07:52:30 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:30 music systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 09 07:52:30 music systemd[1]: volumio.service: Consumed 27.062s CPU time. Feb 09 07:52:30 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:52:30 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:52:30 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 52541. Feb 09 07:52:30 music systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 09 07:52:30 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 09 07:52:30 music systemd[1]: volumio.service: Consumed 27.062s CPU time. Feb 09 07:52:30 music systemd[1]: Started volumio.service - Volumio Backend Module. Feb 09 07:52:30 music systemd[1]: dynamicswap.service: Deactivated successfully. Feb 09 07:52:32 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Feb 09 07:52:32 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:32 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:32 music go-librespot[22317]: go-librespot daemon starting... Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=debug msg="app state loaded" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:32 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:32 music volumio[22302]: info: ----- Volumio3 ---- Feb 09 07:52:32 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:32 music volumio[22302]: info: ----- System startup ---- Feb 09 07:52:32 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=info msg="zeroconf server listening on port 33375" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=debug msg="obtained new client token: AABLjHu8HYfmWiuyCtMngeLq1NydJKHZDdyeqL+NV7BgpRdA/1vRZMQzcofru3P0W5RSl3oq5cxQWR1lk7bqNtttlZpXouZfApjVLzqXZA9qxaxO9Yg705/8/a7JwNMSZO2HuofgZ2+QaioIbEaB9+BxzznQcl+2/BP7R2uKtZNA65XTQ94RsmPKziVlprHqWvsXVkltCvg3m8CKrY4tRswmp9/F/OHJqLXu2DV+hzjndIOLCvsam1w=" Feb 09 07:52:32 music go-librespot[22318]: time="2026-02-09T07:52:32-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="completed challenge" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:33 music volumio[22302]: info: MYVOLUMIO Environment detected Feb 09 07:52:33 music volumio[22302]: info: Plugin folders cleanup Feb 09 07:52:33 music volumio[22302]: info: Scanning into folder /volumio/app/plugins/ Feb 09 07:52:33 music volumio[22302]: info: Scanning category audio_interface Feb 09 07:52:33 music volumio[22302]: info: Scanning category miscellanea Feb 09 07:52:33 music volumio[22302]: info: Scanning category music_service Feb 09 07:52:33 music volumio[22302]: info: Scanning category plugins.json Feb 09 07:52:33 music volumio[22302]: info: Scanning category system_controller Feb 09 07:52:33 music volumio[22302]: info: Scanning category user_interface Feb 09 07:52:33 music volumio[22302]: info: Scanning into folder /data/plugins/ Feb 09 07:52:33 music volumio[22302]: info: Scanning category music_service Feb 09 07:52:33 music volumio[22302]: info: Plugin folders cleanup completed Feb 09 07:52:33 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:33 music volumio[22302]: info: ----- Core plugins startup ---- Feb 09 07:52:33 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:33 music volumio[22302]: info: Loading plugins from folder /volumio/app/plugins/ Feb 09 07:52:33 music volumio[22302]: info: Adding plugin upnp to MyMusic Plugins Feb 09 07:52:33 music volumio[22302]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 09 07:52:33 music volumio[22302]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 09 07:52:33 music volumio[22302]: info: Loading plugins from folder /data/plugins/ Feb 09 07:52:33 music volumio[22302]: info: Loading plugin "system"... Feb 09 07:52:33 music volumio[22302]: info: Loading plugin "appearance"... Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=debug msg="completed challenge" Feb 09 07:52:33 music go-librespot[22318]: time="2026-02-09T07:52:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:34 music go-librespot[22318]: time="2026-02-09T07:52:34-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "network"... Feb 09 07:52:34 music volumio[22302]: info: Refreshing Cached IP Addresses Feb 09 07:52:34 music go-librespot[22318]: time="2026-02-09T07:52:34-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:34 music go-librespot[22318]: time="2026-02-09T07:52:34-05:00" level=debug msg="completed challenge" Feb 09 07:52:34 music sudo[22340]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:52:34 music sudo[22340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:34 music sudo[22342]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:52:34 music sudo[22342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:34 music sudo[22340]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:34 music sudo[22342]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "services"... Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "alsa_controller"... Feb 09 07:52:34 music sudo[22349]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 09 07:52:34 music sudo[22349]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:34 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "wizard"... Feb 09 07:52:34 music go-librespot[22318]: time="2026-02-09T07:52:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "networkfs"... Feb 09 07:52:34 music volumio[22302]: info: Starting Udev Watcher for removable devices Feb 09 07:52:34 music volumio[22302]: info: Ignoring mount for partition: boot Feb 09 07:52:34 music volumio[22302]: info: Ignoring mount for partition: volumio Feb 09 07:52:34 music volumio[22302]: info: Ignoring mount for partition: volumio_data Feb 09 07:52:34 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "volumio_command_line_client"... Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "upnp"... Feb 09 07:52:34 music volumio[22302]: info: [1770641554844] Starting Upmpd Daemon Feb 09 07:52:34 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "my_music"... Feb 09 07:52:34 music volumio[22302]: info: Loading plugin "mpd"... Feb 09 07:52:35 music volumio[22302]: info: Loading plugin "upnp_browser"... Feb 09 07:52:35 music sudo[22349]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:35 music volumio-remote-updater[30265]: [2026-02-09 07:52:35] [connect] Successful connection Feb 09 07:52:35 music go-librespot[22318]: time="2026-02-09T07:52:35-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:52:35 music go-librespot[22318]: time="2026-02-09T07:52:35-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:35 music go-librespot[22318]: time="2026-02-09T07:52:35-05:00" level=debug msg="completed challenge" Feb 09 07:52:35 music go-librespot[22318]: time="2026-02-09T07:52:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="completed challenge" Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:36 music volumio[22302]: info: Starting UPNP Browser Feb 09 07:52:36 music volumio[22302]: info: Loading plugin "alarm-clock"... Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:52:36 music volumio[22302]: info: Loading plugin "airplay_emulation"... Feb 09 07:52:36 music volumio[22302]: info: Starting Shairport Sync Feb 09 07:52:36 music volumio[22302]: info: Loading plugin "last_100"... Feb 09 07:52:36 music volumio[22302]: info: Loading plugin "webradio"... Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:36 music go-librespot[22318]: time="2026-02-09T07:52:36-05:00" level=debug msg="completed challenge" Feb 09 07:52:37 music go-librespot[22318]: time="2026-02-09T07:52:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:37 music go-librespot[22318]: time="2026-02-09T07:52:37-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:37 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:37 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:37 music volumio[22302]: info: Loading plugin "i2s_dacs"... Feb 09 07:52:37 music volumio[22302]: info: I2S DAC not set, start Auto-detection Feb 09 07:52:37 music volumio[22302]: info: Loading plugin "volumiodiscovery"... Feb 09 07:52:37 music volumio[22302]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:37 music volumio[22302]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:37 music volumio[22302]: *** WARNING *** For more information see Feb 09 07:52:37 music volumio[22302]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:37 music volumio[22302]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:37 music volumio[22302]: *** WARNING *** For more information see Feb 09 07:52:37 music node[22302]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:37 music node[22302]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:37 music node[22302]: *** WARNING *** For more information see Feb 09 07:52:37 music node[22302]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 09 07:52:37 music node[22302]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 09 07:52:37 music node[22302]: *** WARNING *** For more information see Feb 09 07:52:37 music volumio[22302]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 09 07:52:37 music volumio[22302]: info: Discovery: Started advertising with name: music Feb 09 07:52:37 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 09 07:52:37 music volumio[22302]: info: Loading plugin "spop"... Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "outputs"... Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "albumart"... Feb 09 07:52:38 music volumio[22302]: info: Plugin example_plugin is not enabled Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "inputs"... Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "updater_comm"... Feb 09 07:52:38 music volumio[22302]: info: Plugin mpdemulation is not enabled Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "rest_api"... Feb 09 07:52:38 music volumio[22302]: info: Loading plugin "websocket"... Feb 09 07:52:38 music volumio[22302]: info: Starting Socket.io Server version 1.7.4 Feb 09 07:52:38 music volumio[22302]: info: Loading i18n strings for locale en Feb 09 07:52:38 music volumio[22302]: Updating browse sources language Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::initPlayerControls Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:38 music volumio[22302]: Express server listening on port 3000 Feb 09 07:52:38 music volumio[22302]: [Metrics] WebUI: 6s 638.44ms Feb 09 07:52:38 music volumio[22302]: info: CoreStateMachine::resetVolumioState Feb 09 07:52:38 music volumio[22302]: info: CoreStateMachine::getcurrentVolume Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:38 music volumio[22302]: info: Volumio Network Manager: Network status updated: 1 Feb 09 07:52:38 music volumio-remote-updater[30265]: [2026-02-09 07:52:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770641555 101 Feb 09 07:52:38 music volumio[22375]: Forking 3 albumart workers Feb 09 07:52:38 music volumio[22302]: 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 Feb 09 07:52:38 music volumio[22302]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:52:38 music volumio[22302]: info: CoreStateMachine::pushState Feb 09 07:52:38 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:38 music volumio[22302]: info: CoreStateMachine::updateTrackBlock Feb 09 07:52:38 music volumio[22302]: info: CorePlayQueue::getTrackBlock Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::volumioRetrievevolume Feb 09 07:52:38 music volumio[22302]: info: Reloading queue from file Feb 09 07:52:38 music volumio[22302]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:38 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: CoreStateMachine::setRepeat null single undefined Feb 09 07:52:39 music volumio[22302]: info: CoreStateMachine::pushState Feb 09 07:52:39 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:39 music volumio[22302]: info: CoreStateMachine::setRandom null Feb 09 07:52:39 music volumio[22302]: info: CoreStateMachine::pushState Feb 09 07:52:39 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:39 music volumio[22302]: info: Setting Device type: Raspberry PI Feb 09 07:52:39 music volumio[22302]: info: VolumeController:: Volume=86 Mute =false Feb 09 07:52:39 music volumio[22302]: info: CoreStateMachine::pushState Feb 09 07:52:39 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioPushState Feb 09 07:52:39 music volumio[22302]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:52:39 music volumio[22302]: info: Discovery: Found device music Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:39 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Feb 09 07:52:39 music volumio[22302]: info: Discovery: Found device music Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:39 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:39 music volumio[22302]: info: Completed loading Core Plugins Feb 09 07:52:39 music volumio[22302]: info: Preparing to generate the ALSA configuration file Feb 09 07:52:39 music volumio[22302]: info: Asound.conf file unchanged, so no further update is needed Feb 09 07:52:39 music volumio[22302]: info: Output device has changed, restarting MPD Feb 09 07:52:39 music volumio[22302]: info: Output device has changed, restarting Shairport Sync Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:39 music sudo[22430]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:52:39 music sudo[22430]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:39 music sudo[22430]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:39 music sudo[22431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:52:39 music sudo[22431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:39 music volumio[22302]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:39 music volumio[22302]: info: ___________ START PLUGINS ___________ Feb 09 07:52:39 music volumio[22302]: info: ControllerMpd::onStart: Initializing MPD Feb 09 07:52:39 music volumio[22302]: info: Creating MPD Configuration file Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:39 music volumio[22302]: info: [1770641559388] CoreMusicLibrary::Adding element Media Servers Feb 09 07:52:39 music systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:39 music volumio[22302]: info: UPNP Browser: Client initialized successfully Feb 09 07:52:39 music sudo[22439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:39 music sudo[22439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:39 music sudo[22439]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:39 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:52:39 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:52:39 music systemd[1]: mpd.service: Consumed 4.149s CPU time. Feb 09 07:52:39 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:52:39 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:52:39 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:52:39 music sudo[22441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 09 07:52:39 music sudo[22441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:39 music volumio[22302]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:39 music volumio[22302]: info: [1770641559541] CoreMusicLibrary::Adding element Last_100 Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 09 07:52:39 music volumio[22302]: info: [1770641559546] CoreMusicLibrary::Adding element Webradio Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 09 07:52:39 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:39 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:52:39 music volumio[22302]: info: Initializing BBC Radios Feb 09 07:52:39 music systemd[1]: mpd.service: Deactivated successfully. Feb 09 07:52:39 music systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 09 07:52:39 music systemd[1]: mpd.socket: Deactivated successfully. Feb 09 07:52:39 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 09 07:52:39 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 09 07:52:39 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 09 07:52:39 music systemd[1]: Starting mpd.service - Music Player Daemon... Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:39 music volumio[22302]: info: Creating Spotify config file Feb 09 07:52:39 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:39 music sudo[22460]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 09 07:52:39 music sudo[22460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 09 07:52:39 music sudo[22460]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:40 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 09 07:52:40 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:40 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:40 music go-librespot[22471]: go-librespot daemon starting... Feb 09 07:52:40 music go-librespot[22472]: time="2026-02-09T07:52:40-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:40 music volumio[22302]: info: Volumio Calling Home Feb 09 07:52:40 music volumio[22391]: Starting albumart workers Feb 09 07:52:40 music go-librespot[22472]: time="2026-02-09T07:52:40-05:00" level=info msg="zeroconf server listening on port 46799" Feb 09 07:52:40 music volumio[22390]: Starting albumart workers Feb 09 07:52:41 music volumio[22392]: Starting albumart workers Feb 09 07:52:41 music volumio[22302]: info: MPD Permissions set Feb 09 07:52:41 music volumio[22302]: info: MPD Permissions set Feb 09 07:52:41 music volumio[22302]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 09 07:52:41 music volumio[22302]: info: Spotify config file written Feb 09 07:52:41 music sudo[22486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 09 07:52:41 music sudo[22486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:41 music volumio[22302]: info: Volumio called home Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 09 07:52:41 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 09 07:52:41 music volumio[22302]: info: No need to fix Spotify hosts Feb 09 07:52:41 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:41 music go-librespot[22500]: go-librespot daemon starting... Feb 09 07:52:41 music sudo[22486]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:41 music go-librespot[22501]: time="2026-02-09T07:52:41-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:41 music go-librespot[22501]: time="2026-02-09T07:52:41-05:00" level=debug msg="app state loaded" Feb 09 07:52:41 music go-librespot[22501]: time="2026-02-09T07:52:41-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:42 music volumio[22302]: info: Starting Shairport Sync Feb 09 07:52:42 music volumio[22302]: info: Starting Shairport Sync Feb 09 07:52:42 music volumio[22302]: info: Starting Shairport Sync Feb 09 07:52:42 music sudo[22518]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:42 music sudo[22518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=info msg="zeroconf server listening on port 39859" Feb 09 07:52:42 music sudo[22522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:42 music sudo[22522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:42 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:52:42 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:52:42 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:42 music systemd[1]: shairport-sync.service: Consumed 1.828s CPU time. Feb 09 07:52:42 music sudo[22528]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 09 07:52:42 music sudo[22528]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:42 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:42 music sudo[22518]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="obtained new client token: AADNtOnamcKEoVtQtKF5AMa5K5FuXxGLInet9wWgyh4CHxECu6LJL3m1s/VLEiIVl47EmEFOTftdUcXi0VqlpABJ7gle/tY/CUDkkl8ehMFBbanW097tLm4ZmbVVmyLvTv7Mc7LQbshAZ1/xNoFYOMgo/xdANO21Uk5A/FCn+K8Me6Kcwu52PNZRYnfI9GvzPkHA7eCeS6Bga1235PTRa/m78PiT+KNecBEkSGAJptlgoFHF5GmADVg=" Feb 09 07:52:42 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 09 07:52:42 music systemd[1]: shairport-sync.service: Deactivated successfully. Feb 09 07:52:42 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:42 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 09 07:52:42 music sudo[22528]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:42 music sudo[22522]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=debug msg="completed challenge" Feb 09 07:52:42 music volumio[22302]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 09 07:52:42 music go-librespot[22501]: time="2026-02-09T07:52:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:42 music volumio[22302]: info: Shairport-Sync Started Feb 09 07:52:42 music volumio[22302]: Error adding Membership: Error: addMembership EINVAL Feb 09 07:52:42 music volumio[22302]: info: Shairport-Sync Started Feb 09 07:52:42 music volumio[22302]: info: Shairport-Sync Started Feb 09 07:52:42 music volumio[22302]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:42 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:43 music go-librespot[22501]: time="2026-02-09T07:52:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:52:43 music go-librespot[22501]: time="2026-02-09T07:52:43-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:43 music go-librespot[22501]: time="2026-02-09T07:52:43-05:00" level=debug msg="completed challenge" Feb 09 07:52:43 music go-librespot[22501]: time="2026-02-09T07:52:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:43 music go-librespot[22501]: time="2026-02-09T07:52:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=debug msg="completed challenge" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:44 music mpd[22470]: 2026-02-09T07:52:44 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 09 07:52:44 music systemd[1]: Started mpd.service - Music Player Daemon. Feb 09 07:52:44 music sudo[22441]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:44 music sudo[22431]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:44 music volumio[22302]: info: Completed starting Core Plugins Feb 09 07:52:44 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:44 music volumio[22302]: info: ----- MyVolumio plugins startup ---- Feb 09 07:52:44 music volumio[22302]: info: ------------------------------------------- Feb 09 07:52:44 music volumio[22302]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 09 07:52:44 music volumio[22302]: error: MPD error: The expression evaluated to a falsy value: Feb 09 07:52:44 music volumio[22302]: assert.ok(self.idling) Feb 09 07:52:44 music volumio[22302]: error: The expression evaluated to a falsy value: Feb 09 07:52:44 music volumio[22302]: assert.ok(self.idling) Feb 09 07:52:44 music volumio[22302]: info: MPD running with PID22470 Feb 09 07:52:44 music volumio[22302]: ,establishing connection Feb 09 07:52:44 music volumio[22302]: error: updateQueue error: null Feb 09 07:52:44 music volumio[22302]: error: updateQueue error: null Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=debug msg="completed challenge" Feb 09 07:52:44 music go-librespot[22501]: time="2026-02-09T07:52:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:44 music sudo[22574]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 09 07:52:44 music sudo[22574]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:44 music sudo[22574]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:44 music sudo[22576]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 09 07:52:44 music sudo[22576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:44 music sudo[22576]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:44 music sudo[22579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 09 07:52:44 music sudo[22579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:44 music sudo[22579]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:44 music volumio[22302]: info: Upmpdcli Daemon Started Feb 09 07:52:45 music volumio[22302]: info: go-librespot daemon successfully initialized Feb 09 07:52:45 music go-librespot[22501]: time="2026-02-09T07:52:45-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 09 07:52:45 music go-librespot[22501]: time="2026-02-09T07:52:45-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:45 music go-librespot[22501]: time="2026-02-09T07:52:45-05:00" level=debug msg="completed challenge" Feb 09 07:52:45 music go-librespot[22501]: time="2026-02-09T07:52:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:46 music go-librespot[22501]: time="2026-02-09T07:52:46-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:52:46 music go-librespot[22501]: time="2026-02-09T07:52:46-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:46 music go-librespot[22501]: time="2026-02-09T07:52:46-05:00" level=debug msg="completed challenge" Feb 09 07:52:46 music go-librespot[22501]: time="2026-02-09T07:52:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:46 music go-librespot[22501]: time="2026-02-09T07:52:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:46 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:46 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:47 music sudo[22583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:52:47 music sudo[22583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:47 music sudo[22585]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Feb 09 07:52:47 music sudo[22585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:47 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:52:47 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:52:47 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:47 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:47 music mpd_monitor.sh[22588]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:52:47 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Feb 09 07:52:47 music sudo[22583]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:47 music systemd[1]: mpd_monitor.service: Deactivated successfully. Feb 09 07:52:47 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:47 music volumio[22302]: info: Successfully started MPD Monitor Feb 09 07:52:47 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Feb 09 07:52:47 music sudo[22585]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:47 music mpd_monitor.sh[22590]: MPD Monitor Service: Starting MPD Monitor Service Feb 09 07:52:47 music volumio[22302]: info: Successfully started MPD Monitor Feb 09 07:52:48 music volumio[22302]: info: Initializing connection to go-librespot Websocket Feb 09 07:52:48 music volumio[22302]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:52:48 music volumio[22302]: info: CoreCommandRouter::volumioGetState Feb 09 07:52:48 music volumio[22302]: info: CorePlayQueue::getTrack 0 Feb 09 07:52:48 music volumio[22302]: info: Listing playlists Feb 09 07:52:48 music volumio[22302]: info: Listing playlists Feb 09 07:52:49 music volumio[22302]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 09 07:52:49 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 09 07:52:49 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:49 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 09 07:52:49 music go-librespot[22594]: go-librespot daemon starting... Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=info msg="running go-librespot 0.6.2" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=debug msg="app state loaded" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 09 07:52:49 music go-librespot[22595]: time="2026-02-09T07:52:49-05:00" level=info msg="zeroconf server listening on port 44201" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="obtained new client token: AADpGdTB+gglVCKiF1JcnvdLP9Ut4zihYIJT4XK3tEQ8dDatZl/mpe4cdTUa1GfsTXrQ2FMOoOhZfY4bFPfhhc5eMCi9DNSV9uo4+4vZd3degj/GTGs7xSBwwTIzrkR3CNNwQSnZuFx3GK49CaHiMOELHvn2O3zs3TlCYvDWfR29bTmItxBKloORaLmZxWlaufv8mBuiDw4u4vaR1s8Ea2h3O1xffryPzfR15lBbpon6N7zWuUpD" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="completed challenge" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=debug msg="completed challenge" Feb 09 07:52:50 music go-librespot[22595]: time="2026-02-09T07:52:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:51 music volumio[22302]: info: Initializing connection to go-librespot Websocket Feb 09 07:52:51 music go-librespot[22595]: time="2026-02-09T07:52:51-05:00" level=debug msg="new websocket client" Feb 09 07:52:51 music volumio[22302]: info: Connection to go-librespot Websocket established Feb 09 07:52:51 music go-librespot[22595]: time="2026-02-09T07:52:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Feb 09 07:52:51 music go-librespot[22595]: time="2026-02-09T07:52:51-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:51 music go-librespot[22595]: time="2026-02-09T07:52:51-05:00" level=debug msg="completed challenge" Feb 09 07:52:51 music go-librespot[22595]: time="2026-02-09T07:52:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:52 music go-librespot[22595]: time="2026-02-09T07:52:52-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 09 07:52:52 music go-librespot[22595]: time="2026-02-09T07:52:52-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:52 music go-librespot[22595]: time="2026-02-09T07:52:52-05:00" level=debug msg="completed challenge" Feb 09 07:52:52 music go-librespot[22595]: time="2026-02-09T07:52:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 09 07:52:52 music volumio[22302]: info: Adding plugin bluetooth to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin multiroom to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin metavolumio to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin cd_controller to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 09 07:52:52 music volumio[22302]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 09 07:52:53 music go-librespot[22595]: time="2026-02-09T07:52:53-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Feb 09 07:52:53 music go-librespot[22595]: time="2026-02-09T07:52:53-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:53 music go-librespot[22595]: time="2026-02-09T07:52:53-05:00" level=debug msg="completed challenge" Feb 09 07:52:53 music volumio[22302]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 09 07:52:53 music volumio[22302]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 09 07:52:53 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:53 music volumio[22302]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 09 07:52:53 music volumio[22302]: info: Starting MyVolumio Remote Streaming Endpoints Feb 09 07:52:53 music volumio[22302]: info: MyVolumio login type: Token Feb 09 07:52:53 music volumio[22302]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 09 07:52:53 music volumio[22302]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 09 07:52:53 music go-librespot[22595]: time="2026-02-09T07:52:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:54 music go-librespot[22595]: time="2026-02-09T07:52:54-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 09 07:52:54 music go-librespot[22595]: time="2026-02-09T07:52:54-05:00" level=debug msg="completed keyexchange" Feb 09 07:52:54 music go-librespot[22595]: time="2026-02-09T07:52:54-05:00" level=debug msg="completed challenge" Feb 09 07:52:54 music volumio[22302]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 09 07:52:54 music volumio[22302]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 09 07:52:54 music volumio[22302]: info: Streaming services startup Feb 09 07:52:54 music volumio[22302]: info: Starting Streaming Daemon Feb 09 07:52:54 music sudo[22605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 09 07:52:54 music sudo[22605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 09 07:52:54 music volumio[22302]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 09 07:52:54 music go-librespot[22595]: time="2026-02-09T07:52:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:54 music go-librespot[22595]: time="2026-02-09T07:52:54-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Feb 09 07:52:54 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 09 07:52:54 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 09 07:52:54 music sudo[22605]: pam_unix(sudo:session): session closed for user root Feb 09 07:52:54 music volumio[22302]: info: Getting Spotify volume Feb 09 07:52:54 music volumio[22302]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:54 music volumio[22302]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 09 07:52:54 music volumio[22302]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 09 07:52:54 music volumio[22302]: errno: -111, Feb 09 07:52:54 music volumio[22302]: code: 'ECONNREFUSED', Feb 09 07:52:54 music volumio[22302]: syscall: 'connect', Feb 09 07:52:54 music volumio[22302]: address: '127.0.0.1', Feb 09 07:52:54 music volumio[22302]: port: 9879, Feb 09 07:52:54 music volumio[22302]: response: undefined Feb 09 07:52:54 music volumio[22302]: } Feb 09 07:52:54 music volumio[22302]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 09 07:52:55 music sudo[22640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-09 07:51' Feb 09 07:52:55 music sudo[22640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"