Feb 08 08:44:00 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:00+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 08 08:44:00 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:00+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:00 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:00+02:00" level=debug msg="completed challenge" Feb 08 08:44:00 volumio-stefan volumio[10845]: info: Loading plugin "now_playing"... Feb 08 08:44:00 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:00+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:01 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:01+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "outputs"... Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "albumart"... Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Plugin example_plugin is not enabled Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "inputs"... Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "updater_comm"... Feb 08 08:44:01 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:01+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:01 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:01+02:00" level=debug msg="completed challenge" Feb 08 08:44:01 volumio-stefan sudo[10892]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Plugin mpdemulation is not enabled Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "rest_api"... Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "websocket"... Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Starting Socket.io Server version 1.7.4 Feb 08 08:44:01 volumio-stefan volumio[10845]: info: Loading plugin "backup_restore"... Feb 08 08:44:02 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:02+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:02 volumio-stefan go-librespot[10867]: time="2026-02-08T08:44:02+02: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 08 08:44:02 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:02 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:02 volumio-stefan volumio[10845]: info: Applying required configuration parameters for plugin backup_restore Feb 08 08:44:02 volumio-stefan volumio[10845]: info: Loading plugin "Systeminfo"... Feb 08 08:44:02 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32008. Feb 08 08:44:02 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:02 volumio-stefan volumio[10915]: Forking 3 albumart workers Feb 08 08:44:02 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:02 volumio-stefan upmpdcli[10925]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:44:02 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:02 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:44:02 volumio-stefan volumio[10845]: info: Loading i18n strings for locale en Feb 08 08:44:02 volumio-stefan volumio[10845]: Updating browse sources language Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::initPlayerControls Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:02 volumio-stefan volumio[10845]: Express server listening on port 3000 Feb 08 08:44:02 volumio-stefan volumio[10845]: [Metrics] WebUI: 7s 388.66ms Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreStateMachine::resetVolumioState Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreStateMachine::getcurrentVolume Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioRetrievevolume Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreStateMachine::pushState Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:02 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:02 volumio-stefan volumio[10845]: info: Volumio Network Manager: Network status updated: 2 Feb 08 08:44:02 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770533038 101 Feb 08 08:44:02 volumio-stefan volumio[10845]: 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 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Reloading queue from file Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreStateMachine::setRepeat null single undefined Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreStateMachine::pushState Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreStateMachine::setRandom null Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreStateMachine::pushState Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Setting Device type: Raspberry PI Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Completed loading Core Plugins Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Preparing to generate the ALSA configuration file Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Asound.conf file unchanged, so no further update is needed Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Output device has changed, restarting MPD Feb 08 08:44:03 volumio-stefan volumio[10845]: info: ___________ START PLUGINS ___________ Feb 08 08:44:03 volumio-stefan volumio[10845]: info: ControllerMpd::onStart: Initializing MPD Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Creating MPD Configuration file Feb 08 08:44:03 volumio-stefan sudo[10966]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:03 volumio-stefan sudo[10966]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:03 volumio-stefan sudo[10966]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:03 volumio-stefan sudo[10968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:03 volumio-stefan sudo[10968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:03 volumio-stefan volumio[10845]: info: [1770533043260] CoreMusicLibrary::Adding element Last_100 Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:03 volumio-stefan sudo[10970]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:03 volumio-stefan sudo[10970]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:03 volumio-stefan volumio[10845]: info: [1770533043276] CoreMusicLibrary::Adding element Webradio Feb 08 08:44:03 volumio-stefan sudo[10970]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:03 volumio-stefan sudo[10974]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:03 volumio-stefan sudo[10974]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:03 volumio-stefan systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Initializing BBC Radios Feb 08 08:44:03 volumio-stefan systemd[1]: mpd.service: Deactivated successfully. Feb 08 08:44:03 volumio-stefan systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 08 08:44:03 volumio-stefan systemd[1]: mpd.service: Consumed 3.271s CPU time. Feb 08 08:44:03 volumio-stefan systemd[1]: mpd.socket: Deactivated successfully. Feb 08 08:44:03 volumio-stefan systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 08 08:44:03 volumio-stefan systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:03 volumio-stefan volumio[10845]: info: Creating Spotify config file Feb 08 08:44:03 volumio-stefan systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 08 08:44:03 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:03 volumio-stefan systemd[1]: Starting mpd.service - Music Player Daemon... Feb 08 08:44:03 volumio-stefan volumio[10926]: Starting albumart workers Feb 08 08:44:03 volumio-stefan sudo[10991]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 08 08:44:03 volumio-stefan sudo[10991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 08 08:44:03 volumio-stefan sudo[10991]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:03 volumio-stefan volumio[10928]: Starting albumart workers Feb 08 08:44:03 volumio-stefan volumio[10927]: Starting albumart workers Feb 08 08:44:04 volumio-stefan volumio[10845]: info: [now-playing] ConfigUpdater: config is up to date. Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Volumio Calling Home Feb 08 08:44:04 volumio-stefan volumio[10845]: info: [now-playing] App is listening on port 4004. Feb 08 08:44:04 volumio-stefan volumio[10845]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Discovery: adding 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Discovery: this is already registered, 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:04 volumio-stefan volumio[10845]: info: MPD Permissions set Feb 08 08:44:04 volumio-stefan volumio[10845]: info: MPD Permissions set Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Volumio called home Feb 08 08:44:04 volumio-stefan volumio[10845]: info: Spotify config file written Feb 08 08:44:04 volumio-stefan volumio[10845]: 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 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:04 volumio-stefan sudo[11017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 08:44:04 volumio-stefan sudo[11017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:05 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:05 volumio-stefan go-librespot[11024]: go-librespot daemon starting... Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:05 volumio-stefan volumio[10845]: info: No need to fix Spotify hosts Feb 08 08:44:05 volumio-stefan sudo[11017]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="app state loaded" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:05 volumio-stefan volumio[10845]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:05 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=info msg="zeroconf server listening on port 46555" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="obtained new client token: AAA6s5eID1ZOTga65/X162jSCR/vEFO8Mv0s5BD+XGQzCjIFqNG9iDswkW3SdTFWmn8zbCqo3S3ilJc7PKYnFASwiqMhXtDHPMwLOZ3+ayMlL00+rETo6ZzcHsBj0h2zhkxawB1F4/kS6VEfbLaAvYazJ92s8QAtvV2pgKOIeMusMhF+ADRadmU/cZFStJ0/nZI3qrXRSlDxdmB7QQcnEUIX+H/GZuMkSW9J6teyCV2rmgzh0Gebadk=" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=debug msg="completed challenge" Feb 08 08:44:05 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:05+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:06 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:06+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Feb 08 08:44:06 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:06 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:06+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:06 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:06+02:00" level=debug msg="completed challenge" Feb 08 08:44:06 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:06+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:06 volumio-stefan mpd[10993]: 2026-02-08T08:44:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 08 08:44:06 volumio-stefan systemd[1]: Started mpd.service - Music Player Daemon. Feb 08 08:44:06 volumio-stefan sudo[10974]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:06 volumio-stefan sudo[10968]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:06 volumio-stefan volumio[10845]: info: Completed starting Core Plugins Feb 08 08:44:06 volumio-stefan volumio[10845]: info: ------------------------------------------- Feb 08 08:44:06 volumio-stefan volumio[10845]: info: ----- MyVolumio plugins startup ---- Feb 08 08:44:06 volumio-stefan volumio[10845]: info: ------------------------------------------- Feb 08 08:44:06 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 08 08:44:07 volumio-stefan volumio[10845]: error: MPD error: The expression evaluated to a falsy value: Feb 08 08:44:07 volumio-stefan volumio[10845]: assert.ok(self.idling) Feb 08 08:44:07 volumio-stefan volumio[10845]: error: The expression evaluated to a falsy value: Feb 08 08:44:07 volumio-stefan volumio[10845]: assert.ok(self.idling) Feb 08 08:44:07 volumio-stefan volumio[10845]: info: MPD running with PID10993 Feb 08 08:44:07 volumio-stefan volumio[10845]: ,establishing connection Feb 08 08:44:07 volumio-stefan volumio[10845]: error: updateQueue error: null Feb 08 08:44:07 volumio-stefan volumio[10845]: error: updateQueue error: null Feb 08 08:44:07 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:07+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:07 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:07+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:07 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:07+02:00" level=debug msg="completed challenge" Feb 08 08:44:07 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:07+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:08 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:08+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:44:08 volumio-stefan volumio[10845]: info: go-librespot daemon successfully initialized Feb 08 08:44:08 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:08+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:08 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:08+02:00" level=debug msg="completed challenge" Feb 08 08:44:08 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:08+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:09 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:09+02:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Feb 08 08:44:09 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:09 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:09+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:09 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:09+02:00" level=debug msg="completed challenge" Feb 08 08:44:09 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:09+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:10 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:10+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:10 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:10+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:10 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:10+02:00" level=debug msg="completed challenge" Feb 08 08:44:10 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:10+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:10 volumio-stefan go-librespot[11030]: time="2026-02-08T08:44:10+02: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 08 08:44:10 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:10 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:11 volumio-stefan volumio[10845]: info: Initializing connection to go-librespot Websocket Feb 08 08:44:11 volumio-stefan volumio[10845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:44:11 volumio-stefan volumio[10845]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 08 08:44:13 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 08 08:44:13 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:13 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:13 volumio-stefan go-librespot[11059]: go-librespot daemon starting... Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=debug msg="app state loaded" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=info msg="zeroconf server listening on port 35989" Feb 08 08:44:13 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:13+02:00" level=debug msg="obtained new client token: AABqEQ8LBRYvxp7533hdMHybRnw5WVd+jxOqKEYLaFUzlqa+i1QGhIZRk/rNLwM/HWwD8qlaGPoV63a3QPyYJZLu5EvPD5Oi9utqhLZuawegudJhN7/m4aG+1EW6Jf8bYcvmvStPU1jfPa7MDaCWSXXVtrgbni2PCUtqauBYUW0ylPzHQTSbmrKaFRGDSKAx0luZnhsVZVPpZF81qHIpEzAENlbCwAHFUaPIRcNWz0myjS/+48/IE0g=" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="completed challenge" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:14 volumio-stefan volumio[10845]: info: Initializing connection to go-librespot Websocket Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="new websocket client" Feb 08 08:44:14 volumio-stefan volumio[10845]: info: Connection to go-librespot Websocket established Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=debug msg="completed challenge" Feb 08 08:44:14 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:14+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 08:44:15 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 08:44:15 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:15+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:15 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:15+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:15 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:15+02:00" level=debug msg="completed challenge" Feb 08 08:44:15 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:15+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:16 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 08:44:16 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 08:44:16 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:16 volumio-stefan volumio[10845]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:16 volumio-stefan volumio[10845]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 08:44:16 volumio-stefan volumio[10845]: info: MyVolumio login type: Token Feb 08 08:44:16 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:16+02:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Feb 08 08:44:16 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 08:44:16 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 08:44:16 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:16+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:16 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:16+02:00" level=debug msg="completed challenge" Feb 08 08:44:16 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:16+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:17 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 08:44:17 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 08:44:17 volumio-stefan volumio[10845]: info: Streaming services startup Feb 08 08:44:17 volumio-stefan volumio[10845]: info: Starting Streaming Daemon Feb 08 08:44:17 volumio-stefan sudo[11070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 08:44:17 volumio-stefan sudo[11070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:17 volumio-stefan volumio[10845]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 08:44:17 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:17+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 08 08:44:17 volumio-stefan sudo[11070]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:17 volumio-stefan volumio[10845]: error: Cannot start Volumio Streaming Daemon Feb 08 08:44:17 volumio-stefan volumio[10845]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 08 08:44:17 volumio-stefan volumio[10845]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 08 08:44:17 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:17+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:17 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:17+02:00" level=debug msg="completed challenge" Feb 08 08:44:17 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:17+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:17 volumio-stefan volumio[10845]: info: Getting Spotify volume Feb 08 08:44:17 volumio-stefan volumio[10845]: 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 08 08:44:17 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32009. Feb 08 08:44:17 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:17 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:17 volumio-stefan volumio[10845]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:17 volumio-stefan volumio[10845]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:17 volumio-stefan upmpdcli[11076]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:44:17 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:17 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:44:17 volumio-stefan volumio[10845]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 08 08:44:17 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:17+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:44:18 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:18+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:18 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:18+02:00" level=debug msg="completed challenge" Feb 08 08:44:18 volumio-stefan volumio[10845]: info: MyVolumio token set successfully Feb 08 08:44:18 volumio-stefan volumio[10845]: info: MYVOLUMIO: Adding device Feb 08 08:44:18 volumio-stefan volumio[10845]: info: MYVOLUMIO: Evaluating Server Feb 08 08:44:18 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:18+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:18 volumio-stefan go-librespot[11060]: time="2026-02-08T08:44:18+02: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 08 08:44:18 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:18 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:18 volumio-stefan volumio[10845]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:44:18 volumio-stefan volumio[10845]: Error: socket hang up Feb 08 08:44:18 volumio-stefan volumio[10845]: at connResetException (node:internal/errors:720:14) Feb 08 08:44:18 volumio-stefan volumio[10845]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 08 08:44:18 volumio-stefan volumio[10845]: at Socket.emit (node:events:526:35) Feb 08 08:44:18 volumio-stefan volumio[10845]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 08 08:44:18 volumio-stefan volumio[10845]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 08 08:44:18 volumio-stefan volumio[10845]: code: 'ECONNRESET', Feb 08 08:44:18 volumio-stefan volumio[10845]: response: undefined Feb 08 08:44:18 volumio-stefan volumio[10845]: } Feb 08 08:44:18 volumio-stefan volumio[10845]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:44:19 volumio-stefan sudo[11108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 08:43' Feb 08 08:44:19 volumio-stefan sudo[11108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:19 volumio-stefan sudo[11108]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:19 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:19] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 08 08:44:19 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:19] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 08 08:44:19 volumio-stefan systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:19 volumio-stefan systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 08 08:44:19 volumio-stefan systemd[1]: volumio.service: Consumed 25.150s CPU time. Feb 08 08:44:19 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:44:19 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:44:19 volumio-stefan systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10350. Feb 08 08:44:19 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:44:19 volumio-stefan systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 08 08:44:19 volumio-stefan systemd[1]: volumio.service: Consumed 25.150s CPU time. Feb 08 08:44:19 volumio-stefan systemd[1]: Started volumio.service - Volumio Backend Module. Feb 08 08:44:19 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:44:21 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:21 volumio-stefan volumio[11120]: info: ----- Volumio3 ---- Feb 08 08:44:21 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:21 volumio-stefan volumio[11120]: info: ----- System startup ---- Feb 08 08:44:21 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:21 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Feb 08 08:44:21 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:21 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:21 volumio-stefan go-librespot[11141]: go-librespot daemon starting... Feb 08 08:44:21 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:21+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:21 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:21+02:00" level=debug msg="app state loaded" Feb 08 08:44:21 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=info msg="zeroconf server listening on port 40017" Feb 08 08:44:22 volumio-stefan volumio[11120]: info: MYVOLUMIO Environment detected Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="obtained new client token: AACUGtDczEuGyPVeHbmQtNVBaRgHn6BF7Gr+Xeya/BrVbELzIzQ8TZE8eh3mHZCiTJIUWUJlJJ4CKNMeHiS0mB2PIv5ZdIePHedHfwgDLjE4XuF9ZqnVPoiVyATKWjZ1qaBSFq6O3oTjO+eDjUyko5DvvId/kWfXh6O0KpKpOA/oYZ3a/9Tqy4leNr01UVUT3UBbe8ZcR2UyxvE4RxqY3GIq0MdU4gdMGGSUQvNtMfTlRHIYcd02V24=" Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Plugin folders cleanup Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning into folder /volumio/app/plugins/ Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category audio_interface Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category miscellanea Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category music_service Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category plugins.json Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category system_controller Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category user_interface Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning into folder /data/plugins/ Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category music_service Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category system_controller Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Scanning category user_interface Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Plugin folders cleanup completed Feb 08 08:44:22 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:22 volumio-stefan volumio[11120]: info: ----- Core plugins startup ---- Feb 08 08:44:22 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Loading plugins from folder /volumio/app/plugins/ Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Adding plugin upnp to MyMusic Plugins Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Loading plugins from folder /data/plugins/ Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Loading plugin "system"... Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:22 volumio-stefan volumio[11120]: info: Loading plugin "appearance"... Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=debug msg="completed challenge" Feb 08 08:44:22 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:22+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="completed challenge" Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "network"... Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Refreshing Cached IP Addresses Feb 08 08:44:23 volumio-stefan sudo[11158]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 08:44:23 volumio-stefan sudo[11158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "services"... Feb 08 08:44:23 volumio-stefan sudo[11158]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:23 volumio-stefan sudo[11160]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "alsa_controller"... Feb 08 08:44:23 volumio-stefan sudo[11160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:23 volumio-stefan sudo[11160]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:23 volumio-stefan sudo[11173]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 08 08:44:23 volumio-stefan sudo[11173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:23 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "wizard"... Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "networkfs"... Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Starting Udev Watcher for removable devices Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Ignoring mount for partition: boot Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Ignoring mount for partition: volumio Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Ignoring mount for partition: volumio_data Feb 08 08:44:23 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "volumio_command_line_client"... Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Plugin upnp is not enabled Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "my_music"... Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "mpd"... Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Plugin upnp_browser is not enabled Feb 08 08:44:23 volumio-stefan volumio[11120]: info: Loading plugin "alarm-clock"... Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:23 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:23+02:00" level=debug msg="completed challenge" Feb 08 08:44:24 volumio-stefan volumio[11120]: info: Plugin airplay_emulation is not enabled Feb 08 08:44:24 volumio-stefan volumio[11120]: info: Loading plugin "last_100"... Feb 08 08:44:24 volumio-stefan volumio[11120]: info: Loading plugin "webradio"... Feb 08 08:44:24 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:24+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:24 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:24] [connect] Successful connection Feb 08 08:44:24 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:24+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:25 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:25+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:25 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:25+02:00" level=debug msg="completed challenge" Feb 08 08:44:25 volumio-stefan volumio[11120]: info: Loading plugin "i2s_dacs"... Feb 08 08:44:25 volumio-stefan volumio[11120]: info: Loading plugin "volumiodiscovery"... Feb 08 08:44:25 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:25+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** For more information see Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:25 volumio-stefan volumio[11120]: *** WARNING *** For more information see Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** For more information see Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:25 volumio-stefan node[11120]: *** WARNING *** For more information see Feb 08 08:44:25 volumio-stefan volumio[11120]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 08 08:44:25 volumio-stefan volumio[11120]: info: Discovery: Started advertising with name: Volumio Stefan Feb 08 08:44:25 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:44:25 volumio-stefan volumio[11120]: info: Loading plugin "spop"... Feb 08 08:44:25 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:25+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:44:26 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:26+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:26 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:26+02:00" level=debug msg="completed challenge" Feb 08 08:44:26 volumio-stefan volumio[11120]: info: Loading plugin "now_playing"... Feb 08 08:44:26 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:26+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:26 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:26+02: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 08 08:44:27 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:27+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:27 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:27+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:27 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:27+02:00" level=debug msg="completed challenge" Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "outputs"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "albumart"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Plugin example_plugin is not enabled Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "inputs"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "updater_comm"... Feb 08 08:44:27 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:27+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:27 volumio-stefan go-librespot[11142]: time="2026-02-08T08:44:27+02: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 08 08:44:27 volumio-stefan sudo[11173]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:27 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:27 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Plugin mpdemulation is not enabled Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "rest_api"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "websocket"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Starting Socket.io Server version 1.7.4 Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "backup_restore"... Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Applying required configuration parameters for plugin backup_restore Feb 08 08:44:27 volumio-stefan volumio[11120]: info: Loading plugin "Systeminfo"... Feb 08 08:44:27 volumio-stefan volumio[11190]: Forking 3 albumart workers Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Loading i18n strings for locale en Feb 08 08:44:28 volumio-stefan volumio[11120]: Updating browse sources language Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::initPlayerControls Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: Express server listening on port 3000 Feb 08 08:44:28 volumio-stefan volumio[11120]: [Metrics] WebUI: 7s 330.23ms Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::resetVolumioState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::getcurrentVolume Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioRetrievevolume Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::pushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Volumio Network Manager: Network status updated: 2 Feb 08 08:44:28 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:28] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770533064 101 Feb 08 08:44:28 volumio-stefan volumio[11120]: 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 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Reloading queue from file Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::setRepeat null single undefined Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::pushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::setRandom null Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreStateMachine::pushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Setting Device type: Raspberry PI Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Completed loading Core Plugins Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Preparing to generate the ALSA configuration file Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Asound.conf file unchanged, so no further update is needed Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Output device has changed, restarting MPD Feb 08 08:44:28 volumio-stefan volumio[11120]: info: ___________ START PLUGINS ___________ Feb 08 08:44:28 volumio-stefan sudo[11243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:28 volumio-stefan sudo[11243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:28 volumio-stefan volumio[11120]: info: ControllerMpd::onStart: Initializing MPD Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Creating MPD Configuration file Feb 08 08:44:28 volumio-stefan sudo[11241]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:28 volumio-stefan sudo[11241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:28 volumio-stefan sudo[11241]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:28 volumio-stefan volumio[11120]: info: [1770533068879] CoreMusicLibrary::Adding element Last_100 Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:28 volumio-stefan systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:28 volumio-stefan volumio[11120]: info: [1770533068896] CoreMusicLibrary::Adding element Webradio Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:28 volumio-stefan sudo[11248]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:28 volumio-stefan sudo[11248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:28 volumio-stefan sudo[11249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:28 volumio-stefan sudo[11249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:28 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:28 volumio-stefan sudo[11249]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:28 volumio-stefan systemd[1]: mpd.service: Deactivated successfully. Feb 08 08:44:28 volumio-stefan systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 08 08:44:28 volumio-stefan systemd[1]: mpd.service: Consumed 3.277s CPU time. Feb 08 08:44:28 volumio-stefan systemd[1]: mpd.socket: Deactivated successfully. Feb 08 08:44:28 volumio-stefan systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 08 08:44:28 volumio-stefan systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 08 08:44:28 volumio-stefan volumio[11120]: info: Initializing BBC Radios Feb 08 08:44:29 volumio-stefan systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 08 08:44:29 volumio-stefan systemd[1]: Starting mpd.service - Music Player Daemon... Feb 08 08:44:29 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:29 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:29 volumio-stefan volumio[11120]: info: Creating Spotify config file Feb 08 08:44:29 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:29 volumio-stefan sudo[11263]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 08 08:44:29 volumio-stefan sudo[11263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 08 08:44:29 volumio-stefan sudo[11263]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:29 volumio-stefan volumio[11201]: Starting albumart workers Feb 08 08:44:29 volumio-stefan volumio[11200]: Starting albumart workers Feb 08 08:44:29 volumio-stefan volumio[11202]: Starting albumart workers Feb 08 08:44:29 volumio-stefan volumio[11120]: info: [now-playing] ConfigUpdater: config is up to date. Feb 08 08:44:29 volumio-stefan volumio[11120]: info: Volumio Calling Home Feb 08 08:44:30 volumio-stefan volumio[11120]: info: [now-playing] App is listening on port 4004. Feb 08 08:44:30 volumio-stefan volumio[11120]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Discovery: adding 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Discovery: this is already registered, 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:30 volumio-stefan volumio[11120]: info: MPD Permissions set Feb 08 08:44:30 volumio-stefan volumio[11120]: info: MPD Permissions set Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Spotify config file written Feb 08 08:44:30 volumio-stefan sudo[11274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 08:44:30 volumio-stefan sudo[11274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:30 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:30 volumio-stefan volumio[11120]: 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 08 08:44:30 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:30 volumio-stefan go-librespot[11279]: go-librespot daemon starting... Feb 08 08:44:30 volumio-stefan sudo[11274]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:30 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:30+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:30 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:30+02:00" level=debug msg="app state loaded" Feb 08 08:44:30 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:30 volumio-stefan volumio[11120]: info: Volumio called home Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:30 volumio-stefan volumio[11120]: info: No need to fix Spotify hosts Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=info msg="zeroconf server listening on port 41247" Feb 08 08:44:31 volumio-stefan volumio[11120]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="obtained new client token: AAAJoxkC82mN6m0Gwb8oo1bNBHtQmwBS18VZlFGp0xBAVsTSV9ft6Ue5ZB3S/UyBtDsRAH3zThNZD0maskF1eeotB0uxJWpOGywR3xg0Flf0A5xMnvsod5DlF34qewxUCXKaFW3cx7NS9XNo9WzpzKRQDrZRCy401B6AQ+hlDSxbKUqkU1ij7/gPPObVFG31+T+N0kW31eULqURvW6NAau7j9S1/0eCCrRoVnyMK4tKOcfv5mlBl" Feb 08 08:44:31 volumio-stefan volumio[11120]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:31 volumio-stefan volumio[11120]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="completed challenge" Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:31 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:31+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=debug msg="completed challenge" Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:32 volumio-stefan mpd[11268]: 2026-02-08T08:44:32 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 08 08:44:32 volumio-stefan systemd[1]: Started mpd.service - Music Player Daemon. Feb 08 08:44:32 volumio-stefan sudo[11248]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:32 volumio-stefan sudo[11243]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:32 volumio-stefan volumio[11120]: info: Completed starting Core Plugins Feb 08 08:44:32 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:32 volumio-stefan volumio[11120]: info: ----- MyVolumio plugins startup ---- Feb 08 08:44:32 volumio-stefan volumio[11120]: info: ------------------------------------------- Feb 08 08:44:32 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 08 08:44:32 volumio-stefan volumio[11120]: error: MPD error: The expression evaluated to a falsy value: Feb 08 08:44:32 volumio-stefan volumio[11120]: assert.ok(self.idling) Feb 08 08:44:32 volumio-stefan volumio[11120]: error: The expression evaluated to a falsy value: Feb 08 08:44:32 volumio-stefan volumio[11120]: assert.ok(self.idling) Feb 08 08:44:32 volumio-stefan volumio[11120]: error: updateQueue error: null Feb 08 08:44:32 volumio-stefan volumio[11120]: info: MPD running with PID11268 Feb 08 08:44:32 volumio-stefan volumio[11120]: ,establishing connection Feb 08 08:44:32 volumio-stefan volumio[11120]: error: updateQueue error: null Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:32 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32010. Feb 08 08:44:32 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=debug msg="completed challenge" Feb 08 08:44:32 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:32 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:32+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:32 volumio-stefan upmpdcli[11321]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:44:32 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:32 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:44:33 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:33+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:33 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:33+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:33 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:33+02:00" level=debug msg="completed challenge" Feb 08 08:44:33 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:33+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:34 volumio-stefan volumio[11120]: info: go-librespot daemon successfully initialized Feb 08 08:44:34 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:34+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:44:34 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:34+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:34 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:34+02:00" level=debug msg="completed challenge" Feb 08 08:44:34 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:34+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:35 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:35+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:44:35 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:35+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:35 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:35+02:00" level=debug msg="completed challenge" Feb 08 08:44:35 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:35+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:35 volumio-stefan go-librespot[11284]: time="2026-02-08T08:44:35+02: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 08 08:44:35 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:35 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:37 volumio-stefan volumio[11120]: info: Initializing connection to go-librespot Websocket Feb 08 08:44:37 volumio-stefan volumio[11120]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:44:37 volumio-stefan volumio[11120]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 08 08:44:38 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Feb 08 08:44:38 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:38 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:38 volumio-stefan go-librespot[11336]: go-librespot daemon starting... Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=debug msg="app state loaded" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=info msg="zeroconf server listening on port 37241" Feb 08 08:44:38 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:38+02:00" level=debug msg="obtained new client token: AADf/viBp3uluA9mXXwFoQhd1eWx7XNW0rca0AV1AAYA6YaIXBW/DxT8W6R//umzHhxIk29pIuN1eACuQ4EJzB31xDsR2hPeK1tEdKJzLpPWO9Z3iNA5KvLtJMbDd35r943u99PxuNS42IJCv5JPsT6hmf0OHTFiRLd/RonO42Q9EfiB7fG9fwOt4Rl8Z+hj+Qo0EJSh3aj2iukzCDup6KetL2X1Fk792SPYnwYtp8HkKe8mJEuv4nM=" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="completed challenge" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=debug msg="completed challenge" Feb 08 08:44:39 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:39+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Initializing connection to go-librespot Websocket Feb 08 08:44:40 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:40+02:00" level=debug msg="new websocket client" Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Connection to go-librespot Websocket established Feb 08 08:44:40 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:40+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:40 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:40+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:40 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:40+02:00" level=debug msg="completed challenge" Feb 08 08:44:40 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:40+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 08:44:40 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 08:44:41 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:41+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:41 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:41+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:41 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:41+02:00" level=debug msg="completed challenge" Feb 08 08:44:41 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:41+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:41 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 08:44:41 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 08:44:41 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:41 volumio-stefan volumio[11120]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:41 volumio-stefan volumio[11120]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 08:44:41 volumio-stefan volumio[11120]: info: MyVolumio login type: Token Feb 08 08:44:41 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 08:44:41 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 08:44:42 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:42+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:44:42 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:42+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:42 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:42+02:00" level=debug msg="completed challenge" Feb 08 08:44:42 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:42+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:42 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 08:44:42 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 08:44:42 volumio-stefan volumio[11120]: info: Streaming services startup Feb 08 08:44:42 volumio-stefan volumio[11120]: info: Starting Streaming Daemon Feb 08 08:44:42 volumio-stefan sudo[11347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 08:44:42 volumio-stefan sudo[11347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:42 volumio-stefan volumio[11120]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 08:44:42 volumio-stefan sudo[11347]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:42 volumio-stefan volumio[11120]: error: Cannot start Volumio Streaming Daemon Feb 08 08:44:42 volumio-stefan volumio[11120]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 08 08:44:42 volumio-stefan volumio[11120]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 08 08:44:43 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:43+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:44:43 volumio-stefan volumio[11120]: info: Getting Spotify volume Feb 08 08:44:43 volumio-stefan volumio[11120]: 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 08 08:44:43 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:43+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:43 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:43+02:00" level=debug msg="completed challenge" Feb 08 08:44:43 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:43+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:43 volumio-stefan go-librespot[11337]: time="2026-02-08T08:44:43+02: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 08 08:44:43 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:43 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:43 volumio-stefan volumio[11120]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:44:43 volumio-stefan volumio[11120]: Error: socket hang up Feb 08 08:44:43 volumio-stefan volumio[11120]: at connResetException (node:internal/errors:720:14) Feb 08 08:44:43 volumio-stefan volumio[11120]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 08 08:44:43 volumio-stefan volumio[11120]: at Socket.emit (node:events:526:35) Feb 08 08:44:43 volumio-stefan volumio[11120]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 08 08:44:43 volumio-stefan volumio[11120]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 08 08:44:43 volumio-stefan volumio[11120]: code: 'ECONNRESET', Feb 08 08:44:43 volumio-stefan volumio[11120]: response: undefined Feb 08 08:44:43 volumio-stefan volumio[11120]: } Feb 08 08:44:43 volumio-stefan volumio[11120]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:44:43 volumio-stefan sudo[11381]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 08:43' Feb 08 08:44:43 volumio-stefan sudo[11381]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:44 volumio-stefan sudo[11381]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:44 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:44] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 08 08:44:44 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:44] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 08 08:44:44 volumio-stefan systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:44 volumio-stefan systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 08 08:44:44 volumio-stefan systemd[1]: volumio.service: Consumed 25.000s CPU time. Feb 08 08:44:44 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:44:44 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:44:44 volumio-stefan systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10351. Feb 08 08:44:44 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:44:44 volumio-stefan systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 08 08:44:44 volumio-stefan systemd[1]: volumio.service: Consumed 25.000s CPU time. Feb 08 08:44:44 volumio-stefan systemd[1]: Started volumio.service - Volumio Backend Module. Feb 08 08:44:44 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:44:46 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Feb 08 08:44:46 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:46 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:46 volumio-stefan go-librespot[11414]: go-librespot daemon starting... Feb 08 08:44:46 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:46 volumio-stefan volumio[11393]: info: ----- Volumio3 ---- Feb 08 08:44:46 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:46 volumio-stefan volumio[11393]: info: ----- System startup ---- Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="app state loaded" Feb 08 08:44:46 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=info msg="zeroconf server listening on port 33343" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="obtained new client token: AAAqdHdNhiHngyE50sNSi/HNF0pi0Ri9SsTGbTjS7DJRfy2XRf/po8iFSYrzn1mVAAUQgj1RirRY+gCrFNiQJfaYtcXAnv5U3xoaauLCT3yJ7iv97Rk4SDLiXWv8BRmXMcpYPSnY8qts7hPjhdnjo0FclWYUzG5HrWM7NUafNHTPlE9EzhO80dxuoiC9y+8WlLbEEj9ZJ5CrWhXV/qbjvX34L+wVib80R44+OLyhMTkOlI2ZgDyz3Ws=" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=debug msg="completed challenge" Feb 08 08:44:46 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:46+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:47 volumio-stefan volumio[11393]: info: MYVOLUMIO Environment detected Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Plugin folders cleanup Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning into folder /volumio/app/plugins/ Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category audio_interface Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category miscellanea Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category music_service Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category plugins.json Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category system_controller Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category user_interface Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning into folder /data/plugins/ Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category music_service Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category system_controller Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Scanning category user_interface Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Plugin folders cleanup completed Feb 08 08:44:47 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:47 volumio-stefan volumio[11393]: info: ----- Core plugins startup ---- Feb 08 08:44:47 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Loading plugins from folder /volumio/app/plugins/ Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Adding plugin upnp to MyMusic Plugins Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Loading plugins from folder /data/plugins/ Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Loading plugin "system"... Feb 08 08:44:47 volumio-stefan volumio[11393]: info: Loading plugin "appearance"... Feb 08 08:44:47 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:47+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:47 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:47+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:47 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:47+02:00" level=debug msg="completed challenge" Feb 08 08:44:47 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:47+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:47 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32011. Feb 08 08:44:47 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:48 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:44:48 volumio-stefan upmpdcli[11430]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:44:48 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:48 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "network"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Refreshing Cached IP Addresses Feb 08 08:44:48 volumio-stefan sudo[11432]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 08:44:48 volumio-stefan sudo[11432]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:48 volumio-stefan sudo[11432]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:48 volumio-stefan sudo[11434]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 08:44:48 volumio-stefan sudo[11434]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "services"... Feb 08 08:44:48 volumio-stefan sudo[11434]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "alsa_controller"... Feb 08 08:44:48 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:48+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:48 volumio-stefan sudo[11442]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 08 08:44:48 volumio-stefan sudo[11442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:48 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "wizard"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "networkfs"... Feb 08 08:44:48 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:48+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:48 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:48+02:00" level=debug msg="completed challenge" Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Starting Udev Watcher for removable devices Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Ignoring mount for partition: boot Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Ignoring mount for partition: volumio Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Ignoring mount for partition: volumio_data Feb 08 08:44:48 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "volumio_command_line_client"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Plugin upnp is not enabled Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "my_music"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "mpd"... Feb 08 08:44:48 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:48+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Plugin upnp_browser is not enabled Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "alarm-clock"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Plugin airplay_emulation is not enabled Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "last_100"... Feb 08 08:44:48 volumio-stefan volumio[11393]: info: Loading plugin "webradio"... Feb 08 08:44:49 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:49+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:49 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:49] [connect] Successful connection Feb 08 08:44:49 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:49+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:49 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:49+02:00" level=debug msg="completed challenge" Feb 08 08:44:49 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:49+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:49 volumio-stefan volumio[11393]: info: Loading plugin "i2s_dacs"... Feb 08 08:44:50 volumio-stefan volumio[11393]: info: Loading plugin "volumiodiscovery"... Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** For more information see Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:50 volumio-stefan volumio[11393]: *** WARNING *** For more information see Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** For more information see Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:44:50 volumio-stefan node[11393]: *** WARNING *** For more information see Feb 08 08:44:50 volumio-stefan volumio[11393]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 08 08:44:50 volumio-stefan volumio[11393]: info: Discovery: Started advertising with name: Volumio Stefan Feb 08 08:44:50 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:44:50 volumio-stefan volumio[11393]: info: Loading plugin "spop"... Feb 08 08:44:50 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:50+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:44:50 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:50+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:50 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:50+02:00" level=debug msg="completed challenge" Feb 08 08:44:50 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:50+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:51 volumio-stefan volumio[11393]: info: Loading plugin "now_playing"... Feb 08 08:44:51 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:51+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:44:51 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:51+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:51 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:51+02:00" level=debug msg="completed challenge" Feb 08 08:44:51 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:51+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:51 volumio-stefan go-librespot[11415]: time="2026-02-08T08:44:51+02: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 08 08:44:51 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:44:51 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "outputs"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "albumart"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Plugin example_plugin is not enabled Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "inputs"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "updater_comm"... Feb 08 08:44:52 volumio-stefan sudo[11442]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Plugin mpdemulation is not enabled Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "rest_api"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "websocket"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Starting Socket.io Server version 1.7.4 Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "backup_restore"... Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Applying required configuration parameters for plugin backup_restore Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading plugin "Systeminfo"... Feb 08 08:44:52 volumio-stefan volumio[11465]: Forking 3 albumart workers Feb 08 08:44:52 volumio-stefan volumio[11393]: info: Loading i18n strings for locale en Feb 08 08:44:52 volumio-stefan volumio[11393]: Updating browse sources language Feb 08 08:44:52 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::initPlayerControls Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: Express server listening on port 3000 Feb 08 08:44:53 volumio-stefan volumio[11393]: [Metrics] WebUI: 7s 330.14ms Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::resetVolumioState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::getcurrentVolume Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioRetrievevolume Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::pushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Volumio Network Manager: Network status updated: 2 Feb 08 08:44:53 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:44:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770533089 101 Feb 08 08:44:53 volumio-stefan volumio[11393]: 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 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Reloading queue from file Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::setRepeat null single undefined Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::pushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::setRandom null Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreStateMachine::pushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioPushState Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Setting Device type: Raspberry PI Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Completed loading Core Plugins Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Preparing to generate the ALSA configuration file Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Asound.conf file unchanged, so no further update is needed Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Output device has changed, restarting MPD Feb 08 08:44:53 volumio-stefan volumio[11393]: info: ___________ START PLUGINS ___________ Feb 08 08:44:53 volumio-stefan volumio[11393]: info: ControllerMpd::onStart: Initializing MPD Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Creating MPD Configuration file Feb 08 08:44:53 volumio-stefan sudo[11515]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:53 volumio-stefan sudo[11515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:53 volumio-stefan sudo[11515]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:53 volumio-stefan volumio[11393]: info: [1770533093742] CoreMusicLibrary::Adding element Last_100 Feb 08 08:44:53 volumio-stefan sudo[11517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:53 volumio-stefan sudo[11517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:53 volumio-stefan sudo[11519]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:44:53 volumio-stefan sudo[11519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:44:53 volumio-stefan volumio[11393]: info: [1770533093760] CoreMusicLibrary::Adding element Webradio Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:44:53 volumio-stefan sudo[11519]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Initializing BBC Radios Feb 08 08:44:53 volumio-stefan sudo[11522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:44:53 volumio-stefan sudo[11522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:53 volumio-stefan systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:53 volumio-stefan systemd[1]: mpd.service: Deactivated successfully. Feb 08 08:44:53 volumio-stefan systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 08 08:44:53 volumio-stefan systemd[1]: mpd.service: Consumed 3.298s CPU time. Feb 08 08:44:53 volumio-stefan systemd[1]: mpd.socket: Deactivated successfully. Feb 08 08:44:53 volumio-stefan systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 08 08:44:53 volumio-stefan systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 08 08:44:53 volumio-stefan volumio[11393]: info: Creating Spotify config file Feb 08 08:44:53 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:54 volumio-stefan systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 08 08:44:54 volumio-stefan systemd[1]: Starting mpd.service - Music Player Daemon... Feb 08 08:44:54 volumio-stefan volumio[11475]: Starting albumart workers Feb 08 08:44:54 volumio-stefan volumio[11476]: Starting albumart workers Feb 08 08:44:54 volumio-stefan sudo[11540]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 08 08:44:54 volumio-stefan sudo[11540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 08 08:44:54 volumio-stefan sudo[11540]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:54 volumio-stefan volumio[11477]: Starting albumart workers Feb 08 08:44:54 volumio-stefan volumio[11393]: info: [now-playing] ConfigUpdater: config is up to date. Feb 08 08:44:54 volumio-stefan volumio[11393]: info: Volumio Calling Home Feb 08 08:44:54 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Feb 08 08:44:54 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:54 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:54 volumio-stefan go-librespot[11546]: go-librespot daemon starting... Feb 08 08:44:54 volumio-stefan go-librespot[11547]: time="2026-02-08T08:44:54+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:54 volumio-stefan volumio[11393]: info: [now-playing] App is listening on port 4004. Feb 08 08:44:54 volumio-stefan volumio[11393]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Discovery: adding 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Discovery: this is already registered, 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Discovery: Found device Volumio Stefan Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:55 volumio-stefan volumio[11393]: info: MPD Permissions set Feb 08 08:44:55 volumio-stefan volumio[11393]: info: MPD Permissions set Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Spotify config file written Feb 08 08:44:55 volumio-stefan go-librespot[11547]: time="2026-02-08T08:44:55+02:00" level=info msg="zeroconf server listening on port 38105" Feb 08 08:44:55 volumio-stefan sudo[11561]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 08:44:55 volumio-stefan sudo[11561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:44:55 volumio-stefan systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 08:44:55 volumio-stefan systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 08:44:55 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:55 volumio-stefan volumio[11393]: 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 08 08:44:55 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:44:55 volumio-stefan go-librespot[11571]: go-librespot daemon starting... Feb 08 08:44:55 volumio-stefan sudo[11561]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:55 volumio-stefan volumio[11393]: info: Volumio called home Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=debug msg="app state loaded" Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:44:55 volumio-stefan volumio[11393]: info: No need to fix Spotify hosts Feb 08 08:44:55 volumio-stefan volumio[11393]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:44:55 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:55+02:00" level=info msg="zeroconf server listening on port 38907" Feb 08 08:44:56 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioGetState Feb 08 08:44:56 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=debug msg="obtained new client token: AABgJslIwnZJuBi2uUeGrTChHOWKwABKi4x0jdjfWFkX/fSdNBPlbvng+4CpxaTOIUikyC8OKVuw9+mgbFPRbF4/lsbyl3PdPYcK/2to+dbAIsMAQkqrByRF9uyD4uPiai8JNefD4kq2uq2bh7ZFlN7gtlxXuSJgdpPBnHxSceh4rF97SFnOduVEwfWdVtgKQnavq4gu6Kqk1CPv9hBtCEzJzQ+scIQ/cQgL0WLgMwk9I8qhqVT7" Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=debug msg="completed challenge" Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:56 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=debug msg="completed challenge" Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:57 volumio-stefan mpd[11542]: 2026-02-08T08:44:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 08 08:44:57 volumio-stefan systemd[1]: Started mpd.service - Music Player Daemon. Feb 08 08:44:57 volumio-stefan sudo[11522]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:57 volumio-stefan sudo[11517]: pam_unix(sudo:session): session closed for user root Feb 08 08:44:57 volumio-stefan volumio[11393]: info: Completed starting Core Plugins Feb 08 08:44:57 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:57 volumio-stefan volumio[11393]: info: ----- MyVolumio plugins startup ---- Feb 08 08:44:57 volumio-stefan volumio[11393]: info: ------------------------------------------- Feb 08 08:44:57 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 08 08:44:57 volumio-stefan volumio[11393]: error: MPD error: The expression evaluated to a falsy value: Feb 08 08:44:57 volumio-stefan volumio[11393]: assert.ok(self.idling) Feb 08 08:44:57 volumio-stefan volumio[11393]: error: The expression evaluated to a falsy value: Feb 08 08:44:57 volumio-stefan volumio[11393]: assert.ok(self.idling) Feb 08 08:44:57 volumio-stefan volumio[11393]: error: updateQueue error: null Feb 08 08:44:57 volumio-stefan volumio[11393]: info: MPD running with PID11542 Feb 08 08:44:57 volumio-stefan volumio[11393]: ,establishing connection Feb 08 08:44:57 volumio-stefan volumio[11393]: error: updateQueue error: null Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:57 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:57+02:00" level=debug msg="completed challenge" Feb 08 08:44:58 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:58+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:58 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:58+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 08 08:44:58 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:58+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:58 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:58+02:00" level=debug msg="completed challenge" Feb 08 08:44:58 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:58+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:44:58 volumio-stefan volumio[11393]: info: go-librespot daemon successfully initialized Feb 08 08:44:59 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:59+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:44:59 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:59+02:00" level=debug msg="completed keyexchange" Feb 08 08:44:59 volumio-stefan go-librespot[11573]: time="2026-02-08T08:44:59+02:00" level=debug msg="completed challenge" Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=debug msg="completed challenge" Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:00 volumio-stefan go-librespot[11573]: time="2026-02-08T08:45:00+02: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 08 08:45:00 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:00 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:01 volumio-stefan volumio[11393]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:01 volumio-stefan volumio[11393]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:45:02 volumio-stefan volumio[11393]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 08 08:45:03 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32012. Feb 08 08:45:03 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:03 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:03 volumio-stefan upmpdcli[11617]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:45:03 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:03 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:45:03 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 08 08:45:03 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:04 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:04 volumio-stefan go-librespot[11618]: go-librespot daemon starting... Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="app state loaded" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=info msg="zeroconf server listening on port 36545" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="obtained new client token: AAB5GJNrkVrcaD3ZqtGdNU02lYArklfDJqRLz3dd9RGQvtyNzvje7QO7QDO3g9kjOFa5FiODIaMMLPtySPi/hxfVBkXhgGEDepA2W9UBMm78japonjumA2q45K3R+x9UUt7Ci+GDMPXlDN9Arw1eXwIGgHfp/Yos/IOwaDfsCV8f1Tym5X8Uxdu3TIOb17C0HhU5bF6Q92oCNVmDoALhdgnP/XhKTh55UR5iNHop2ZHvr4eM9xDE2HA=" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="completed challenge" Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:04 volumio-stefan volumio[11393]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:04 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:04+02:00" level=debug msg="new websocket client" Feb 08 08:45:04 volumio-stefan volumio[11393]: info: Connection to go-librespot Websocket established Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="completed challenge" Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:05 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:05+02:00" level=debug msg="completed challenge" Feb 08 08:45:06 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:06+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 08:45:06 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 08:45:06 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:06+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:45:06 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:06+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:06 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:06+02:00" level=debug msg="completed challenge" Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 08:45:07 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:07 volumio-stefan volumio[11393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:07 volumio-stefan volumio[11393]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 08:45:07 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:07+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:07 volumio-stefan volumio[11393]: info: MyVolumio login type: Token Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 08:45:07 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:07+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:45:07 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:07+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:07 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:07+02:00" level=debug msg="completed challenge" Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 08:45:07 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 08:45:07 volumio-stefan volumio[11393]: info: Streaming services startup Feb 08 08:45:07 volumio-stefan volumio[11393]: info: Starting Streaming Daemon Feb 08 08:45:08 volumio-stefan sudo[11629]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 08:45:08 volumio-stefan sudo[11629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:08 volumio-stefan volumio[11393]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 08:45:08 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:08+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:08 volumio-stefan sudo[11629]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:08 volumio-stefan volumio[11393]: info: Getting Spotify volume Feb 08 08:45:08 volumio-stefan volumio[11393]: error: Cannot start Volumio Streaming Daemon Feb 08 08:45:08 volumio-stefan volumio[11393]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 08 08:45:08 volumio-stefan volumio[11393]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 08 08:45:08 volumio-stefan volumio[11393]: 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 08 08:45:08 volumio-stefan volumio[11393]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:08 volumio-stefan volumio[11393]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:08 volumio-stefan volumio[11393]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 08 08:45:08 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:08+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:45:09 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:09+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:09 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:09+02:00" level=debug msg="completed challenge" Feb 08 08:45:09 volumio-stefan volumio[11393]: info: MyVolumio token set successfully Feb 08 08:45:09 volumio-stefan volumio[11393]: info: MYVOLUMIO: Adding device Feb 08 08:45:09 volumio-stefan volumio[11393]: info: MYVOLUMIO: Evaluating Server Feb 08 08:45:09 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:09+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:09 volumio-stefan go-librespot[11619]: time="2026-02-08T08:45:09+02: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 08 08:45:09 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:09 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:09 volumio-stefan volumio[11393]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:45:09 volumio-stefan volumio[11393]: Error: socket hang up Feb 08 08:45:09 volumio-stefan volumio[11393]: at connResetException (node:internal/errors:720:14) Feb 08 08:45:09 volumio-stefan volumio[11393]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 08 08:45:09 volumio-stefan volumio[11393]: at Socket.emit (node:events:526:35) Feb 08 08:45:09 volumio-stefan volumio[11393]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 08 08:45:09 volumio-stefan volumio[11393]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 08 08:45:09 volumio-stefan volumio[11393]: code: 'ECONNRESET', Feb 08 08:45:09 volumio-stefan volumio[11393]: response: undefined Feb 08 08:45:09 volumio-stefan volumio[11393]: } Feb 08 08:45:09 volumio-stefan volumio[11393]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:45:10 volumio-stefan sudo[11665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 08:44' Feb 08 08:45:10 volumio-stefan sudo[11665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:10 volumio-stefan sudo[11665]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:10 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:10] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 08 08:45:10 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:10] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 08 08:45:10 volumio-stefan systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:10 volumio-stefan systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 08 08:45:10 volumio-stefan systemd[1]: volumio.service: Consumed 25.267s CPU time. Feb 08 08:45:10 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:45:10 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:45:10 volumio-stefan systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10352. Feb 08 08:45:10 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:45:10 volumio-stefan systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 08 08:45:10 volumio-stefan systemd[1]: volumio.service: Consumed 25.267s CPU time. Feb 08 08:45:10 volumio-stefan systemd[1]: Started volumio.service - Volumio Backend Module. Feb 08 08:45:10 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:45:12 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:12 volumio-stefan volumio[11685]: info: ----- Volumio3 ---- Feb 08 08:45:12 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:12 volumio-stefan volumio[11685]: info: ----- System startup ---- Feb 08 08:45:12 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:12 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Feb 08 08:45:12 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:12 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:12 volumio-stefan go-librespot[11707]: go-librespot daemon starting... Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=debug msg="app state loaded" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:45:12 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:12+02:00" level=info msg="zeroconf server listening on port 38739" Feb 08 08:45:13 volumio-stefan volumio[11685]: info: MYVOLUMIO Environment detected Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="obtained new client token: AADXPyZuv8eV2HAwiaATWnB7wcvc80aTs+UAH2SkV35CFgVaH7qCZgeKBotNMuej2q7hg101h0zxDGSDGb5kIX27FLg050gKkI26T2xH5cUsDZqCaqWFH31Z1wYekeDoGiOVRkzhDi9G1rDaa7HpJXDTu+Tq6dhbLIHK1Sl9d4MBvFddKkxsE/dM3TcW7dK1sEc1iXyFgUcyE8eKMmDXg0h1ecj2llD4MXKstknw4jHNxDWOFOTf" Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Plugin folders cleanup Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning into folder /volumio/app/plugins/ Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category audio_interface Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category miscellanea Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category music_service Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category plugins.json Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category system_controller Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category user_interface Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning into folder /data/plugins/ Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category music_service Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category system_controller Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Scanning category user_interface Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Plugin folders cleanup completed Feb 08 08:45:13 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:13 volumio-stefan volumio[11685]: info: ----- Core plugins startup ---- Feb 08 08:45:13 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Loading plugins from folder /volumio/app/plugins/ Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Adding plugin upnp to MyMusic Plugins Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Loading plugins from folder /data/plugins/ Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Loading plugin "system"... Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:13 volumio-stefan volumio[11685]: info: Loading plugin "appearance"... Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="completed challenge" Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=debug msg="completed challenge" Feb 08 08:45:13 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:13+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "network"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Refreshing Cached IP Addresses Feb 08 08:45:14 volumio-stefan sudo[11724]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 08:45:14 volumio-stefan sudo[11724]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:14 volumio-stefan sudo[11724]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:14 volumio-stefan sudo[11726]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 08:45:14 volumio-stefan sudo[11726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:14 volumio-stefan sudo[11726]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "services"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "alsa_controller"... Feb 08 08:45:14 volumio-stefan sudo[11734]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 08 08:45:14 volumio-stefan sudo[11734]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:14 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "wizard"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "networkfs"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Starting Udev Watcher for removable devices Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Ignoring mount for partition: boot Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Ignoring mount for partition: volumio Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Ignoring mount for partition: volumio_data Feb 08 08:45:14 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "volumio_command_line_client"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Plugin upnp is not enabled Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "my_music"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "mpd"... Feb 08 08:45:14 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Plugin upnp_browser is not enabled Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "alarm-clock"... Feb 08 08:45:14 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:14+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:14 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:14+02:00" level=debug msg="completed challenge" Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Plugin airplay_emulation is not enabled Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "last_100"... Feb 08 08:45:14 volumio-stefan volumio[11685]: info: Loading plugin "webradio"... Feb 08 08:45:14 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:14+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:15 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:15] [connect] Successful connection Feb 08 08:45:15 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:15+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:45:15 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:15+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:15 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:15+02:00" level=debug msg="completed challenge" Feb 08 08:45:15 volumio-stefan volumio[11685]: info: Loading plugin "i2s_dacs"... Feb 08 08:45:15 volumio-stefan volumio[11685]: info: Loading plugin "volumiodiscovery"... Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** For more information see Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:15 volumio-stefan volumio[11685]: *** WARNING *** For more information see Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** For more information see Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:15 volumio-stefan node[11685]: *** WARNING *** For more information see Feb 08 08:45:15 volumio-stefan volumio[11685]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 08 08:45:15 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:15+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:15 volumio-stefan volumio[11685]: info: Discovery: Started advertising with name: Volumio Stefan Feb 08 08:45:16 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:45:16 volumio-stefan volumio[11685]: info: Loading plugin "spop"... Feb 08 08:45:16 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Feb 08 08:45:16 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:16+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:16 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:16+02:00" level=debug msg="completed challenge" Feb 08 08:45:16 volumio-stefan volumio[11685]: info: Loading plugin "now_playing"... Feb 08 08:45:17 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:17+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:17 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:17+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "outputs"... Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "albumart"... Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Plugin example_plugin is not enabled Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "inputs"... Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "updater_comm"... Feb 08 08:45:18 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:18+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:18 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:18+02:00" level=debug msg="completed challenge" Feb 08 08:45:18 volumio-stefan sudo[11734]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Plugin mpdemulation is not enabled Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "rest_api"... Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "websocket"... Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Starting Socket.io Server version 1.7.4 Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "backup_restore"... Feb 08 08:45:18 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32013. Feb 08 08:45:18 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:18 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:18+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:18 volumio-stefan go-librespot[11708]: time="2026-02-08T08:45:18+02: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 08 08:45:18 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:18 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:18 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Applying required configuration parameters for plugin backup_restore Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading plugin "Systeminfo"... Feb 08 08:45:18 volumio-stefan upmpdcli[11766]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:45:18 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:18 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:45:18 volumio-stefan volumio[11756]: Forking 3 albumart workers Feb 08 08:45:18 volumio-stefan volumio[11685]: info: Loading i18n strings for locale en Feb 08 08:45:18 volumio-stefan volumio[11685]: Updating browse sources language Feb 08 08:45:18 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::initPlayerControls Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: Express server listening on port 3000 Feb 08 08:45:19 volumio-stefan volumio[11685]: [Metrics] WebUI: 7s 321.19ms Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::resetVolumioState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::getcurrentVolume Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioRetrievevolume Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::pushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Volumio Network Manager: Network status updated: 2 Feb 08 08:45:19 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770533115 101 Feb 08 08:45:19 volumio-stefan volumio[11685]: 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 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Reloading queue from file Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::setRepeat null single undefined Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::pushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::setRandom null Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreStateMachine::pushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Setting Device type: Raspberry PI Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Completed loading Core Plugins Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Preparing to generate the ALSA configuration file Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Asound.conf file unchanged, so no further update is needed Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Output device has changed, restarting MPD Feb 08 08:45:19 volumio-stefan volumio[11685]: info: ___________ START PLUGINS ___________ Feb 08 08:45:19 volumio-stefan volumio[11685]: info: ControllerMpd::onStart: Initializing MPD Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Creating MPD Configuration file Feb 08 08:45:19 volumio-stefan sudo[11808]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:45:19 volumio-stefan sudo[11808]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:19 volumio-stefan sudo[11808]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:45:19 volumio-stefan volumio[11685]: info: [1770533119632] CoreMusicLibrary::Adding element Last_100 Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:19 volumio-stefan sudo[11810]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:45:19 volumio-stefan sudo[11810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:45:19 volumio-stefan volumio[11685]: info: [1770533119642] CoreMusicLibrary::Adding element Webradio Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:19 volumio-stefan sudo[11813]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:45:19 volumio-stefan sudo[11813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:19 volumio-stefan sudo[11813]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Initializing BBC Radios Feb 08 08:45:19 volumio-stefan sudo[11816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:45:19 volumio-stefan sudo[11816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:19 volumio-stefan systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:19 volumio-stefan systemd[1]: mpd.service: Deactivated successfully. Feb 08 08:45:19 volumio-stefan systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 08 08:45:19 volumio-stefan systemd[1]: mpd.service: Consumed 3.310s CPU time. Feb 08 08:45:19 volumio-stefan systemd[1]: mpd.socket: Deactivated successfully. Feb 08 08:45:19 volumio-stefan systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 08 08:45:19 volumio-stefan systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 08 08:45:19 volumio-stefan volumio[11685]: info: Creating Spotify config file Feb 08 08:45:19 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:19 volumio-stefan systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 08 08:45:19 volumio-stefan systemd[1]: Starting mpd.service - Music Player Daemon... Feb 08 08:45:20 volumio-stefan volumio[11767]: Starting albumart workers Feb 08 08:45:20 volumio-stefan sudo[11833]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 08 08:45:20 volumio-stefan sudo[11833]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 08 08:45:20 volumio-stefan sudo[11833]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:20 volumio-stefan volumio[11768]: Starting albumart workers Feb 08 08:45:20 volumio-stefan volumio[11769]: Starting albumart workers Feb 08 08:45:20 volumio-stefan volumio[11685]: info: [now-playing] ConfigUpdater: config is up to date. Feb 08 08:45:20 volumio-stefan volumio[11685]: info: Volumio Calling Home Feb 08 08:45:20 volumio-stefan volumio[11685]: info: [now-playing] App is listening on port 4004. Feb 08 08:45:21 volumio-stefan volumio[11685]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Discovery: adding 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Discovery: Found device Volumio Stefan Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Discovery: this is already registered, 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Discovery: Found device Volumio Stefan Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:21 volumio-stefan volumio[11685]: info: MPD Permissions set Feb 08 08:45:21 volumio-stefan volumio[11685]: info: MPD Permissions set Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Volumio called home Feb 08 08:45:21 volumio-stefan volumio[11685]: info: Spotify config file written Feb 08 08:45:21 volumio-stefan sudo[11858]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 08:45:21 volumio-stefan sudo[11858]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:21 volumio-stefan volumio[11685]: 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 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:21 volumio-stefan go-librespot[11862]: go-librespot daemon starting... Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:21 volumio-stefan volumio[11685]: info: No need to fix Spotify hosts Feb 08 08:45:21 volumio-stefan sudo[11858]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=debug msg="app state loaded" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:21 volumio-stefan volumio[11685]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:21 volumio-stefan volumio[11685]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=info msg="zeroconf server listening on port 46019" Feb 08 08:45:21 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:21+02:00" level=debug msg="obtained new client token: AAB48IE5a09gkqI9JfZZuI1J3FfRPDXHhleuA9uOZqfmsh9wp02J5bpcqDhJ7HedZ7fbkzKnKVmKkaTpHSOXiWEc60tTdIk8nqwUohoXKrCHWi++MmUZQhUtnwiPTriwyuQ6g/Ltu2fxuQ/dbhBwqlOlLToQ1pY94zhIVXmCxcNSo7LUQn6KnQvHoUZv7QKS4QonTCrHuRbUwvDRQVE+54+Bv0p+Pg30C3LZSXdx/xiwqXyh5lIPzNY=" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="completed challenge" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=debug msg="completed challenge" Feb 08 08:45:22 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:22+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:23 volumio-stefan mpd[11835]: 2026-02-08T08:45:23 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 08 08:45:23 volumio-stefan systemd[1]: Started mpd.service - Music Player Daemon. Feb 08 08:45:23 volumio-stefan sudo[11810]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:23 volumio-stefan sudo[11816]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:23 volumio-stefan volumio[11685]: info: Completed starting Core Plugins Feb 08 08:45:23 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:23 volumio-stefan volumio[11685]: info: ----- MyVolumio plugins startup ---- Feb 08 08:45:23 volumio-stefan volumio[11685]: info: ------------------------------------------- Feb 08 08:45:23 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 08 08:45:23 volumio-stefan volumio[11685]: error: MPD error: The expression evaluated to a falsy value: Feb 08 08:45:23 volumio-stefan volumio[11685]: assert.ok(self.idling) Feb 08 08:45:23 volumio-stefan volumio[11685]: error: The expression evaluated to a falsy value: Feb 08 08:45:23 volumio-stefan volumio[11685]: assert.ok(self.idling) Feb 08 08:45:23 volumio-stefan volumio[11685]: info: MPD running with PID11835 Feb 08 08:45:23 volumio-stefan volumio[11685]: ,establishing connection Feb 08 08:45:23 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:23 volumio-stefan volumio[11685]: error: updateQueue error: null Feb 08 08:45:23 volumio-stefan volumio[11685]: error: updateQueue error: null Feb 08 08:45:23 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:23+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:23 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:23+02:00" level=debug msg="completed challenge" Feb 08 08:45:23 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:23+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:24 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:24+02:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Feb 08 08:45:24 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:24+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:45:24 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:24+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:24 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:24+02:00" level=debug msg="completed challenge" Feb 08 08:45:24 volumio-stefan volumio[11685]: info: go-librespot daemon successfully initialized Feb 08 08:45:24 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:24+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:25 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:25+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:45:25 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:25+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:25 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:25+02:00" level=debug msg="completed challenge" Feb 08 08:45:25 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:25+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:25 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:25+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Feb 08 08:45:26 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:26+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:26 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:26+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:26 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:26+02:00" level=debug msg="completed challenge" Feb 08 08:45:26 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:26+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:26 volumio-stefan go-librespot[11871]: time="2026-02-08T08:45:26+02: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 08 08:45:26 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:26 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:27 volumio-stefan volumio[11685]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:27 volumio-stefan volumio[11685]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:45:28 volumio-stefan volumio[11685]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 08 08:45:29 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Feb 08 08:45:29 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:29 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:29 volumio-stefan go-librespot[11899]: go-librespot daemon starting... Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="app state loaded" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=info msg="zeroconf server listening on port 34899" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="obtained new client token: AAB7zEjLQIQBCpfHxZWQNIa/ZLEqNVxP6x2Wf27qXWRUiaDYHIvySersPLFlgbK31GdyVlouFpIR+UsSfm2tj17Ur2XarwU+ghmM5tyUE7uc0Vcq4tbTdO2lUT3v1RfHwzzCbWKZIz4+kfm2i6OkinXeLK4P6bC4w8rN5wIii20jV7fQwpYZYae1oJwhJlwZs1OsoXlyw0awyHsMrB+MRU7zktQ8o7qj+J9CjL7PbAhnH24zv0KsS94=" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=debug msg="completed challenge" Feb 08 08:45:29 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:29+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:30 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:30+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:30 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:30+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:30 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:30+02:00" level=debug msg="completed challenge" Feb 08 08:45:30 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:30+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:30 volumio-stefan volumio[11685]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:30 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:30+02:00" level=debug msg="new websocket client" Feb 08 08:45:30 volumio-stefan volumio[11685]: info: Connection to go-librespot Websocket established Feb 08 08:45:31 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:31+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:31 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:31+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:31 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:31+02:00" level=debug msg="completed challenge" Feb 08 08:45:31 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:31+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:31 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:31+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 08:45:31 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 08:45:32 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:32+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:32 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:32+02:00" level=debug msg="completed challenge" Feb 08 08:45:32 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:32+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:32 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 08:45:32 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 08:45:32 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:32 volumio-stefan volumio[11685]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:32 volumio-stefan volumio[11685]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 08:45:32 volumio-stefan volumio[11685]: info: MyVolumio login type: Token Feb 08 08:45:32 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:32+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:45:32 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 08:45:32 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=debug msg="completed challenge" Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:33 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32014. Feb 08 08:45:33 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 08:45:33 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 08:45:33 volumio-stefan volumio[11685]: info: Streaming services startup Feb 08 08:45:33 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:33 volumio-stefan volumio[11685]: info: Starting Streaming Daemon Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:45:33 volumio-stefan sudo[11912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 08:45:33 volumio-stefan sudo[11912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:33 volumio-stefan volumio[11685]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=debug msg="completed challenge" Feb 08 08:45:33 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:33 volumio-stefan sudo[11912]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:33 volumio-stefan upmpdcli[11910]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:33 volumio-stefan go-librespot[11900]: time="2026-02-08T08:45:33+02: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 08 08:45:33 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:33 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:45:33 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:33 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:33 volumio-stefan volumio[11685]: info: Getting Spotify volume Feb 08 08:45:33 volumio-stefan volumio[11685]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:45:33 volumio-stefan volumio[11685]: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:45:33 volumio-stefan volumio[11685]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Feb 08 08:45:33 volumio-stefan volumio[11685]: errno: -111, Feb 08 08:45:33 volumio-stefan volumio[11685]: code: 'ECONNREFUSED', Feb 08 08:45:33 volumio-stefan volumio[11685]: syscall: 'connect', Feb 08 08:45:33 volumio-stefan volumio[11685]: address: '127.0.0.1', Feb 08 08:45:33 volumio-stefan volumio[11685]: port: 9879, Feb 08 08:45:33 volumio-stefan volumio[11685]: response: undefined Feb 08 08:45:33 volumio-stefan volumio[11685]: } Feb 08 08:45:33 volumio-stefan volumio[11685]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:45:34 volumio-stefan sudo[11947]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 08:44' Feb 08 08:45:34 volumio-stefan sudo[11947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:34 volumio-stefan sudo[11947]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:35 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:35] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Feb 08 08:45:35 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:35] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Feb 08 08:45:35 volumio-stefan systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:35 volumio-stefan systemd[1]: volumio.service: Failed with result 'exit-code'. Feb 08 08:45:35 volumio-stefan systemd[1]: volumio.service: Consumed 24.726s CPU time. Feb 08 08:45:35 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:45:35 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:45:35 volumio-stefan systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10353. Feb 08 08:45:35 volumio-stefan systemd[1]: Started dynamicswap.service - dynamicswap service. Feb 08 08:45:35 volumio-stefan systemd[1]: Stopped volumio.service - Volumio Backend Module. Feb 08 08:45:35 volumio-stefan systemd[1]: volumio.service: Consumed 24.726s CPU time. Feb 08 08:45:35 volumio-stefan systemd[1]: Started volumio.service - Volumio Backend Module. Feb 08 08:45:35 volumio-stefan systemd[1]: dynamicswap.service: Deactivated successfully. Feb 08 08:45:36 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Feb 08 08:45:36 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:37 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:37 volumio-stefan go-librespot[11978]: go-librespot daemon starting... Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="app state loaded" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=info msg="zeroconf server listening on port 33659" Feb 08 08:45:37 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:37 volumio-stefan volumio[11963]: info: ----- Volumio3 ---- Feb 08 08:45:37 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:37 volumio-stefan volumio[11963]: info: ----- System startup ---- Feb 08 08:45:37 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="obtained new client token: AAA1TtwClqYqZTZwpK5PxAqW3FwNEgot6QJyP+B03H81e/vI+qVK0BUii+2zQb25BPmbpoUNd4ADpVGcKzoA7b20HByjPkKPuxUb3Dc2ug648Xe3JehmcsCpD2zVXBBZOKNinITBKQtWRAJvNW4lwdc0viMetjMuutGGS9ZTY5o7zYMSN7s9rQcoTJIEbbPP9ILkswfsLEbdEyFwI3siezrs4z+ugH3I3NtLQM0zHeeiiDWrlPDAXcc=" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=debug msg="completed challenge" Feb 08 08:45:37 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:37+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:38 volumio-stefan volumio[11963]: info: MYVOLUMIO Environment detected Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Plugin folders cleanup Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning into folder /volumio/app/plugins/ Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category audio_interface Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category miscellanea Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category music_service Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category plugins.json Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category system_controller Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category user_interface Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning into folder /data/plugins/ Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category music_service Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category system_controller Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Scanning category user_interface Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Plugin folders cleanup completed Feb 08 08:45:38 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:38 volumio-stefan volumio[11963]: info: ----- Core plugins startup ---- Feb 08 08:45:38 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Loading plugins from folder /volumio/app/plugins/ Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Adding plugin upnp to MyMusic Plugins Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Loading plugins from folder /data/plugins/ Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Loading plugin "system"... Feb 08 08:45:38 volumio-stefan volumio[11963]: info: Loading plugin "appearance"... Feb 08 08:45:38 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:38+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Feb 08 08:45:38 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:38+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:38 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:38+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:38 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:38+02:00" level=debug msg="completed challenge" Feb 08 08:45:38 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:38+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:39 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:39+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "network"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Refreshing Cached IP Addresses Feb 08 08:45:39 volumio-stefan sudo[12001]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 08 08:45:39 volumio-stefan sudo[12001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:39 volumio-stefan sudo[12003]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 08 08:45:39 volumio-stefan sudo[12003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:39 volumio-stefan sudo[12001]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:39 volumio-stefan sudo[12003]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "services"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "alsa_controller"... Feb 08 08:45:39 volumio-stefan sudo[12012]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Feb 08 08:45:39 volumio-stefan sudo[12012]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:39 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:39+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:39 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:39+02:00" level=debug msg="completed challenge" Feb 08 08:45:39 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "wizard"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "networkfs"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Starting Udev Watcher for removable devices Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Ignoring mount for partition: boot Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Ignoring mount for partition: volumio Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Ignoring mount for partition: volumio_data Feb 08 08:45:39 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "volumio_command_line_client"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Plugin upnp is not enabled Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "my_music"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "mpd"... Feb 08 08:45:39 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:39+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Plugin upnp_browser is not enabled Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "alarm-clock"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Plugin airplay_emulation is not enabled Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "last_100"... Feb 08 08:45:39 volumio-stefan volumio[11963]: info: Loading plugin "webradio"... Feb 08 08:45:40 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:40+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:45:40 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:40] [connect] Successful connection Feb 08 08:45:40 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:40+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:40 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:40+02:00" level=debug msg="completed challenge" Feb 08 08:45:40 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:40+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:41 volumio-stefan volumio[11963]: info: Loading plugin "i2s_dacs"... Feb 08 08:45:41 volumio-stefan volumio[11963]: info: Loading plugin "volumiodiscovery"... Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** For more information see Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:41 volumio-stefan volumio[11963]: *** WARNING *** For more information see Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** For more information see Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 08 08:45:41 volumio-stefan node[11963]: *** WARNING *** For more information see Feb 08 08:45:41 volumio-stefan volumio[11963]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 08 08:45:41 volumio-stefan volumio[11963]: info: Discovery: Started advertising with name: Volumio Stefan Feb 08 08:45:41 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 08 08:45:41 volumio-stefan volumio[11963]: info: Loading plugin "spop"... Feb 08 08:45:41 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:41+02:00" level=debug msg="connected to ap-gae2.spotify.com:80" Feb 08 08:45:41 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:41+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:41 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:41+02:00" level=debug msg="completed challenge" Feb 08 08:45:42 volumio-stefan volumio[11963]: info: Loading plugin "now_playing"... Feb 08 08:45:42 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:42+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:42 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:42+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:42 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:42+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:42 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:42+02:00" level=debug msg="completed challenge" Feb 08 08:45:43 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:43+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:43 volumio-stefan go-librespot[11979]: time="2026-02-08T08:45:43+02: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 08 08:45:43 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:43 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "outputs"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "albumart"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Plugin example_plugin is not enabled Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "inputs"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "updater_comm"... Feb 08 08:45:43 volumio-stefan sudo[12012]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Plugin mpdemulation is not enabled Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "rest_api"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "websocket"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Starting Socket.io Server version 1.7.4 Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "backup_restore"... Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Applying required configuration parameters for plugin backup_restore Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading plugin "Systeminfo"... Feb 08 08:45:43 volumio-stefan volumio[12033]: Forking 3 albumart workers Feb 08 08:45:43 volumio-stefan volumio[11963]: info: Loading i18n strings for locale en Feb 08 08:45:43 volumio-stefan volumio[11963]: Updating browse sources language Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::initPlayerControls Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: Express server listening on port 3000 Feb 08 08:45:44 volumio-stefan volumio[11963]: [Metrics] WebUI: 7s 299.33ms Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::resetVolumioState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::getcurrentVolume Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioRetrievevolume Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::pushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Volumio Network Manager: Network status updated: 2 Feb 08 08:45:44 volumio-stefan volumio-remote-updater[658]: [2026-02-08 08:45:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1770533140 101 Feb 08 08:45:44 volumio-stefan volumio[11963]: 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 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Reloading queue from file Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::setRepeat null single undefined Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::pushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::setRandom null Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreStateMachine::pushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioPushState Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Setting Device type: Raspberry PI Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Completed loading Core Plugins Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Preparing to generate the ALSA configuration file Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Asound.conf file unchanged, so no further update is needed Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Output device has changed, restarting MPD Feb 08 08:45:44 volumio-stefan volumio[11963]: info: ___________ START PLUGINS ___________ Feb 08 08:45:44 volumio-stefan volumio[11963]: info: ControllerMpd::onStart: Initializing MPD Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Creating MPD Configuration file Feb 08 08:45:44 volumio-stefan sudo[12083]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:45:44 volumio-stefan sudo[12083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:44 volumio-stefan sudo[12083]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:44 volumio-stefan sudo[12085]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:45:44 volumio-stefan sudo[12085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:45:44 volumio-stefan volumio[11963]: info: [1770533144672] CoreMusicLibrary::Adding element Last_100 Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:44 volumio-stefan sudo[12090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 08 08:45:44 volumio-stefan sudo[12090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 08 08:45:44 volumio-stefan volumio[11963]: info: [1770533144700] CoreMusicLibrary::Adding element Webradio Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 08 08:45:44 volumio-stefan sudo[12088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 08 08:45:44 volumio-stefan sudo[12088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:44 volumio-stefan sudo[12088]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Initializing BBC Radios Feb 08 08:45:44 volumio-stefan systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:44 volumio-stefan systemd[1]: mpd.service: Deactivated successfully. Feb 08 08:45:44 volumio-stefan systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 08 08:45:44 volumio-stefan systemd[1]: mpd.service: Consumed 3.293s CPU time. Feb 08 08:45:44 volumio-stefan systemd[1]: mpd.socket: Deactivated successfully. Feb 08 08:45:44 volumio-stefan systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 08 08:45:44 volumio-stefan systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 08 08:45:44 volumio-stefan volumio[11963]: info: Creating Spotify config file Feb 08 08:45:44 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:44 volumio-stefan systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 08 08:45:44 volumio-stefan systemd[1]: Starting mpd.service - Music Player Daemon... Feb 08 08:45:45 volumio-stefan volumio[12043]: Starting albumart workers Feb 08 08:45:45 volumio-stefan sudo[12108]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 08 08:45:45 volumio-stefan sudo[12108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 08 08:45:45 volumio-stefan sudo[12108]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:45 volumio-stefan volumio[12045]: Starting albumart workers Feb 08 08:45:45 volumio-stefan volumio[12044]: Starting albumart workers Feb 08 08:45:45 volumio-stefan volumio[11963]: info: [now-playing] ConfigUpdater: config is up to date. Feb 08 08:45:45 volumio-stefan volumio[11963]: info: Volumio Calling Home Feb 08 08:45:46 volumio-stefan volumio[11963]: info: [now-playing] App is listening on port 4004. Feb 08 08:45:46 volumio-stefan volumio[11963]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Feb 08 08:45:46 volumio-stefan volumio[11963]: info: Discovery: adding 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:45:46 volumio-stefan volumio[11963]: info: Discovery: Found device Volumio Stefan Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:46 volumio-stefan volumio[11963]: info: Discovery: this is already registered, 9fd4730c-d5cc-4b0d-8799-894bfe737c6c Feb 08 08:45:46 volumio-stefan volumio[11963]: info: Discovery: Found device Volumio Stefan Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:46 volumio-stefan volumio[11963]: info: MPD Permissions set Feb 08 08:45:46 volumio-stefan volumio[11963]: info: MPD Permissions set Feb 08 08:45:46 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Feb 08 08:45:46 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:46 volumio-stefan volumio[11963]: info: Spotify config file written Feb 08 08:45:46 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:46 volumio-stefan go-librespot[12121]: go-librespot daemon starting... Feb 08 08:45:46 volumio-stefan go-librespot[12126]: time="2026-02-08T08:45:46+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:46 volumio-stefan go-librespot[12126]: time="2026-02-08T08:45:46+02:00" level=debug msg="app state loaded" Feb 08 08:45:46 volumio-stefan go-librespot[12126]: time="2026-02-08T08:45:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:46 volumio-stefan sudo[12134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 08 08:45:46 volumio-stefan sudo[12134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:46 volumio-stefan volumio[11963]: 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 08 08:45:46 volumio-stefan volumio[11963]: info: Volumio called home Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Feb 08 08:45:46 volumio-stefan systemd[1]: go-librespot-daemon.service: Deactivated successfully. Feb 08 08:45:46 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:46 volumio-stefan go-librespot[12149]: go-librespot daemon starting... Feb 08 08:45:46 volumio-stefan sudo[12134]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:46 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:46+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:46+02:00" level=debug msg="app state loaded" Feb 08 08:45:46 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 08 08:45:46 volumio-stefan volumio[11963]: info: No need to fix Spotify hosts Feb 08 08:45:46 volumio-stefan volumio[11963]: info: An error occurred while refreshing Spotify Token Error: Bad Request Feb 08 08:45:46 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=info msg="zeroconf server listening on port 43159" Feb 08 08:45:47 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:47 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="obtained new client token: AABHu2leIETLshhOm3gwHcNYu8G+byjr78ab37QkHZ5SH7MTOLM6Xkjfyy+49QgIVCksylIgWwXY1ijtXTqUkU27BVucaB3mYELM6aXMt6YrcLbR8xFmWAupkf2NvN3MZoZ48OnXahfUmWKf21R1FGnftamgmvbOKBut/99Wk1M+C3Plmi/M8NCRIJyPy+wsC0EuvLg1RScAnOCYbIK/NRehZU7dP/Pef42HgQRZr56q6I1dNvaW" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="completed challenge" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:47 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:47+02:00" level=debug msg="completed challenge" Feb 08 08:45:48 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:48+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:48 volumio-stefan mpd[12110]: 2026-02-08T08:45:48 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 08 08:45:48 volumio-stefan systemd[1]: Started mpd.service - Music Player Daemon. Feb 08 08:45:48 volumio-stefan sudo[12090]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:48 volumio-stefan sudo[12085]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:48 volumio-stefan volumio[11963]: info: Completed starting Core Plugins Feb 08 08:45:48 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:48 volumio-stefan volumio[11963]: info: ----- MyVolumio plugins startup ---- Feb 08 08:45:48 volumio-stefan volumio[11963]: info: ------------------------------------------- Feb 08 08:45:48 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 08 08:45:48 volumio-stefan volumio[11963]: error: MPD error: The expression evaluated to a falsy value: Feb 08 08:45:48 volumio-stefan volumio[11963]: assert.ok(self.idling) Feb 08 08:45:48 volumio-stefan volumio[11963]: error: The expression evaluated to a falsy value: Feb 08 08:45:48 volumio-stefan volumio[11963]: assert.ok(self.idling) Feb 08 08:45:48 volumio-stefan volumio[11963]: error: updateQueue error: null Feb 08 08:45:48 volumio-stefan volumio[11963]: info: MPD running with PID12110 Feb 08 08:45:48 volumio-stefan volumio[11963]: ,establishing connection Feb 08 08:45:48 volumio-stefan volumio[11963]: error: updateQueue error: null Feb 08 08:45:48 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:48+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:48 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:48+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:48 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:48+02:00" level=debug msg="completed challenge" Feb 08 08:45:48 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:48+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:48 volumio-stefan systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 32015. Feb 08 08:45:48 volumio-stefan systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:49 volumio-stefan systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Feb 08 08:45:49 volumio-stefan upmpdcli[12169]: Could not open config: /tmp/upmpdcli.conf Feb 08 08:45:49 volumio-stefan systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:49 volumio-stefan systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 08 08:45:49 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:49+02:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Feb 08 08:45:49 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:49+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:49 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:49+02:00" level=debug msg="completed challenge" Feb 08 08:45:49 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:49+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:49 volumio-stefan volumio[11963]: info: go-librespot daemon successfully initialized Feb 08 08:45:50 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:50+02:00" level=debug msg="connected to ap-gue1.spotify.com:443" Feb 08 08:45:50 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:50+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:50 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:50+02:00" level=debug msg="completed challenge" Feb 08 08:45:50 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:50+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:51 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:51+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:45:51 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:51+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:51 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:51+02:00" level=debug msg="completed challenge" Feb 08 08:45:51 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:51+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:51 volumio-stefan go-librespot[12150]: time="2026-02-08T08:45:51+02: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 08 08:45:51 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:51 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:52 volumio-stefan volumio[11963]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:52 volumio-stefan volumio[11963]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 08 08:45:53 volumio-stefan volumio[11963]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 08 08:45:54 volumio-stefan systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Feb 08 08:45:54 volumio-stefan systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:54 volumio-stefan systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Feb 08 08:45:54 volumio-stefan go-librespot[12186]: go-librespot daemon starting... Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=info msg="running go-librespot 0.6.2" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=debug msg="app state loaded" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=info msg="zeroconf server listening on port 36797" Feb 08 08:45:54 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:54+02:00" level=debug msg="obtained new client token: AAD8spzaejM/eMYJ+9P7hVt+jLv+8Nn8VLiI5T0G/YO9FXSnriSyE31v5M+gZxmViaMTr3edxUKCzrsrHvCAKn14WHNvQJIrYGTb2umWJbn/zrtpx3m48semhZ7j/Q3HzNkCe+55RqfMXNjK4P6udfydGZwLGJFrIAvEsEvqAncTEUVQmzpS0sfZOkA17rYrRXi7dFoUrL/iZqF29llZGWjZsUXo+NxpEfUOJr5O5Pwaq/X96R6cYCU=" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="completed challenge" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="completed challenge" Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:55 volumio-stefan volumio[11963]: info: Initializing connection to go-librespot Websocket Feb 08 08:45:55 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:55+02:00" level=debug msg="new websocket client" Feb 08 08:45:55 volumio-stefan volumio[11963]: info: Connection to go-librespot Websocket established Feb 08 08:45:56 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin bluetooth to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin multiroom to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin metavolumio to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin cd_controller to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 08 08:45:56 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 08 08:45:56 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:56+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:56 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:56+02:00" level=debug msg="completed challenge" Feb 08 08:45:56 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:56+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:57 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 08 08:45:57 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 08 08:45:57 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:57 volumio-stefan volumio[11963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 08 08:45:57 volumio-stefan volumio[11963]: info: Starting MyVolumio Remote Streaming Endpoints Feb 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Feb 08 08:45:57 volumio-stefan volumio[11963]: info: MyVolumio login type: Token Feb 08 08:45:57 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 08 08:45:57 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02: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 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02:00" level=debug msg="connected to ap-gew4.spotify.com:80" Feb 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02:00" level=debug msg="completed challenge" Feb 08 08:45:57 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:57+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:58 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 08 08:45:58 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 08 08:45:58 volumio-stefan volumio[11963]: info: Streaming services startup Feb 08 08:45:58 volumio-stefan volumio[11963]: info: Starting Streaming Daemon Feb 08 08:45:58 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:58+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 08 08:45:58 volumio-stefan sudo[12197]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 08 08:45:58 volumio-stefan sudo[12197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 08 08:45:58 volumio-stefan volumio[11963]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 08 08:45:58 volumio-stefan sudo[12197]: pam_unix(sudo:session): session closed for user root Feb 08 08:45:58 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:58+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:58 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:58+02:00" level=debug msg="completed challenge" Feb 08 08:45:58 volumio-stefan volumio[11963]: error: Cannot start Volumio Streaming Daemon Feb 08 08:45:58 volumio-stefan volumio[11963]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 08 08:45:58 volumio-stefan volumio[11963]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 08 08:45:58 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:58+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:58 volumio-stefan volumio[11963]: info: Getting Spotify volume Feb 08 08:45:59 volumio-stefan volumio[11963]: 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 08 08:45:59 volumio-stefan volumio[11963]: info: CoreCommandRouter::volumioGetState Feb 08 08:45:59 volumio-stefan volumio[11963]: info: CorePlayQueue::getTrack 0 Feb 08 08:45:59 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:59+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 08 08:45:59 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:59+02:00" level=debug msg="completed keyexchange" Feb 08 08:45:59 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:59+02:00" level=debug msg="completed challenge" Feb 08 08:45:59 volumio-stefan volumio[11963]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 08 08:45:59 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:59+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Feb 08 08:45:59 volumio-stefan go-librespot[12187]: time="2026-02-08T08:45:59+02: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 08 08:45:59 volumio-stefan volumio[11963]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:45:59 volumio-stefan systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 08 08:45:59 volumio-stefan systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 08 08:45:59 volumio-stefan volumio[11963]: Error: socket hang up Feb 08 08:45:59 volumio-stefan volumio[11963]: at connResetException (node:internal/errors:720:14) Feb 08 08:45:59 volumio-stefan volumio[11963]: at Socket.socketOnEnd (node:_http_client:519:23) Feb 08 08:45:59 volumio-stefan volumio[11963]: at Socket.emit (node:events:526:35) Feb 08 08:45:59 volumio-stefan volumio[11963]: at endReadableNT (node:internal/streams/readable:1376:12) Feb 08 08:45:59 volumio-stefan volumio[11963]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Feb 08 08:45:59 volumio-stefan volumio[11963]: code: 'ECONNRESET', Feb 08 08:45:59 volumio-stefan volumio[11963]: response: undefined Feb 08 08:45:59 volumio-stefan volumio[11963]: } Feb 08 08:45:59 volumio-stefan volumio[11963]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 08 08:46:00 volumio-stefan sudo[12232]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-08 08:44' Feb 08 08:46:00 volumio-stefan sudo[12232]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"