Jan 11 14:12:00 music sudo[18398]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:12:00 music sudo[18398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:00 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "wizard"... Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "networkfs"... Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=debug msg="completed challenge" Jan 11 14:12:00 music volumio[18349]: info: Starting Udev Watcher for removable devices Jan 11 14:12:00 music volumio[18349]: info: Ignoring mount for partition: boot Jan 11 14:12:00 music volumio[18349]: info: Ignoring mount for partition: volumio Jan 11 14:12:00 music volumio[18349]: info: Ignoring mount for partition: volumio_data Jan 11 14:12:00 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "upnp"... Jan 11 14:12:00 music volumio[18349]: info: [1768158720151] Starting Upmpd Daemon Jan 11 14:12:00 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "my_music"... Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "mpd"... Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:00 music volumio-remote-updater[22000]: [2026-01-11 14:12:00] [connect] Successful connection Jan 11 14:12:00 music volumio[18349]: info: Loading plugin "upnp_browser"... Jan 11 14:12:00 music sudo[18398]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:00 music go-librespot[18365]: time="2026-01-11T14:12:00-05:00" level=debug msg="completed challenge" Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=debug msg="completed challenge" Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:01 music go-librespot[18365]: time="2026-01-11T14:12:01-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:01 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:01 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:02 music volumio[18349]: info: Starting UPNP Browser Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "alarm-clock"... Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "airplay_emulation"... Jan 11 14:12:02 music volumio[18349]: info: Starting Shairport Sync Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "last_100"... Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "webradio"... Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "i2s_dacs"... Jan 11 14:12:02 music volumio[18349]: info: I2S DAC not set, start Auto-detection Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "volumiodiscovery"... Jan 11 14:12:02 music volumio[18349]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:02 music volumio[18349]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:02 music volumio[18349]: *** WARNING *** For more information see Jan 11 14:12:02 music volumio[18349]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:02 music volumio[18349]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:02 music volumio[18349]: *** WARNING *** For more information see Jan 11 14:12:02 music node[18349]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:02 music node[18349]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:02 music node[18349]: *** WARNING *** For more information see Jan 11 14:12:02 music node[18349]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:02 music node[18349]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:02 music node[18349]: *** WARNING *** For more information see Jan 11 14:12:02 music volumio[18349]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:12:02 music volumio[18349]: info: Discovery: Started advertising with name: music Jan 11 14:12:02 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:02 music volumio[18349]: info: Loading plugin "spop"... Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "outputs"... Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "albumart"... Jan 11 14:12:03 music volumio[18349]: info: Plugin example_plugin is not enabled Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "inputs"... Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "updater_comm"... Jan 11 14:12:03 music volumio[18349]: info: Plugin mpdemulation is not enabled Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "rest_api"... Jan 11 14:12:03 music volumio[18349]: info: Loading plugin "websocket"... Jan 11 14:12:03 music volumio[18349]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:12:03 music volumio[18349]: info: Loading i18n strings for locale en Jan 11 14:12:03 music volumio[18349]: Updating browse sources language Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::initPlayerControls Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:03 music volumio[18349]: Express server listening on port 3000 Jan 11 14:12:03 music volumio[18349]: [Metrics] WebUI: 6s 582.48ms Jan 11 14:12:03 music volumio[18349]: info: CoreStateMachine::resetVolumioState Jan 11 14:12:03 music volumio[18349]: info: CoreStateMachine::getcurrentVolume Jan 11 14:12:03 music volumio[18349]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:04 music volumio[18349]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:12:04 music volumio-remote-updater[22000]: [2026-01-11 14:12:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768158720 101 Jan 11 14:12:04 music volumio[18423]: Forking 3 albumart workers Jan 11 14:12:04 music volumio[18349]: 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 Jan 11 14:12:04 music volumio[18349]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::pushState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::updateTrackBlock Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrackBlock Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:04 music volumio[18349]: info: Reloading queue from file Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::pushState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::setRandom null Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::pushState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:04 music volumio[18349]: info: Setting Device type: Raspberry PI Jan 11 14:12:04 music volumio[18349]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:04 music volumio[18349]: info: CoreStateMachine::pushState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:04 music volumio[18349]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:04 music volumio[18349]: info: Discovery: Found device music Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:04 music volumio[18349]: info: Discovery: Found device music Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:04 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:04 music volumio[18349]: info: Completed loading Core Plugins Jan 11 14:12:04 music volumio[18349]: info: Preparing to generate the ALSA configuration file Jan 11 14:12:04 music volumio[18349]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:12:04 music volumio[18349]: info: Output device has changed, restarting MPD Jan 11 14:12:04 music volumio[18349]: info: Output device has changed, restarting Shairport Sync Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:04 music volumio[18349]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:04 music volumio[18349]: info: ___________ START PLUGINS ___________ Jan 11 14:12:04 music sudo[18479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:04 music sudo[18479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:04 music sudo[18477]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:04 music sudo[18477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:04 music volumio[18349]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:12:04 music sudo[18477]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:04 music volumio[18349]: info: Creating MPD Configuration file Jan 11 14:12:04 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:12:04 music sudo[18487]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:04 music sudo[18487]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:04 music volumio[18349]: info: [1768158724674] CoreMusicLibrary::Adding element Media Servers Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:04 music sudo[18487]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:04 music volumio[18349]: info: UPNP Browser: Client initialized successfully Jan 11 14:12:04 music sudo[18489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:04 music sudo[18489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:04 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:04 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:04 music systemd[1]: mpd.service: Consumed 4.153s CPU time. Jan 11 14:12:04 music volumio[18349]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:04 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:04 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:04 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:04 music volumio[18349]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:04 music volumio[18349]: info: [1768158724823] CoreMusicLibrary::Adding element Last_100 Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:04 music volumio[18349]: info: [1768158724828] CoreMusicLibrary::Adding element Webradio Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:04 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:04 music volumio[18349]: info: Initializing BBC Radios Jan 11 14:12:04 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:04 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:04 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:12:04 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:04 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:04 music go-librespot[18506]: go-librespot daemon starting... Jan 11 14:12:04 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:04 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:04 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:04 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:04 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:04 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:04 music go-librespot[18508]: time="2026-01-11T14:12:04-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:04 music go-librespot[18508]: time="2026-01-11T14:12:04-05:00" level=debug msg="app state loaded" Jan 11 14:12:04 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:05 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:05 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:05 music volumio[18349]: info: Creating Spotify config file Jan 11 14:12:05 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:05 music sudo[18520]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:12:05 music sudo[18520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:12:05 music sudo[18520]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=info msg="zeroconf server listening on port 45889" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="obtained new client token: AABF2byZKtYeV8SpbeqNppVumjwPH0FuXo7vXSDdKnsHHwMYM0oZGFW6iyfAds6FLH814zYfb0eZUVzjCuq7jUmQuUE3Udwwf2Q6BcO3Nb67jiXt6UHS5TEGAZbW38yKmySPP/VxHgjt1zfoNIobJGEiT4dYtS0D8TNEyY3LWCI9XW6TfUwaMtoXJ5V0fDqYSFcmeMYdrr5i9vMZU7eihch5Lbk3RjNbbdL94Wuniur3M5r6QFGyMa0=" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:05 music volumio[18349]: info: Volumio Calling Home Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=debug msg="completed challenge" Jan 11 14:12:05 music go-librespot[18508]: time="2026-01-11T14:12:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:06 music volumio[18440]: Starting albumart workers Jan 11 14:12:06 music volumio[18438]: Starting albumart workers Jan 11 14:12:06 music volumio[18439]: Starting albumart workers Jan 11 14:12:06 music go-librespot[18508]: time="2026-01-11T14:12:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:06 music volumio[18349]: info: MPD Permissions set Jan 11 14:12:06 music volumio[18349]: info: MPD Permissions set Jan 11 14:12:06 music go-librespot[18508]: time="2026-01-11T14:12:06-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:06 music go-librespot[18508]: time="2026-01-11T14:12:06-05:00" level=debug msg="completed challenge" Jan 11 14:12:06 music go-librespot[18508]: time="2026-01-11T14:12:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:06 music volumio[18349]: info: Volumio called home Jan 11 14:12:06 music volumio[18349]: info: Spotify config file written Jan 11 14:12:06 music sudo[18535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:12:06 music sudo[18535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:06 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:06 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:06 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:12:06 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:12:06 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:06 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:06 music go-librespot[18537]: go-librespot daemon starting... Jan 11 14:12:06 music sudo[18535]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:06 music go-librespot[18538]: time="2026-01-11T14:12:06-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:06 music go-librespot[18538]: time="2026-01-11T14:12:06-05:00" level=debug msg="app state loaded" Jan 11 14:12:06 music volumio[18349]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:07 music volumio[18349]: info: No need to fix Spotify hosts Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=info msg="zeroconf server listening on port 35741" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="obtained new client token: AAAo077Sn3rsWV0HNigmBRt7VgxtCrFgvIFhU3GsjPzPdpyH8vLiZKXj/o31uzanL1N5dM4cAv8q4ShPxaGYMoBoig+l1l/8jNnd8ef52g8jE78d8AYPZaj8yJdyEvDsSMiB5rncos9Wdpyc8K4EESSs7VjSR4oQtrJOw3euvavlCjgil4J7VSdkF24FGjgnZDDgtJviSUPmqhKtvkYevpaqH+4vlX0HjvLM5WmvgG16/Iy6a6b04mo=" Jan 11 14:12:07 music volumio[18349]: info: Listing playlists Jan 11 14:12:07 music volumio[18349]: info: Listing playlists Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=debug msg="completed challenge" Jan 11 14:12:07 music volumio[18349]: info: Starting Shairport Sync Jan 11 14:12:07 music volumio[18349]: info: Starting Shairport Sync Jan 11 14:12:07 music volumio[18349]: info: Starting Shairport Sync Jan 11 14:12:07 music sudo[18577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:07 music sudo[18577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:07 music sudo[18579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:07 music sudo[18579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:07 music volumio[18349]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:12:07 music go-librespot[18538]: time="2026-01-11T14:12:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:07 music sudo[18581]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:07 music sudo[18581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:07 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:12:07 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:12:07 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:07 music systemd[1]: shairport-sync.service: Consumed 1.869s CPU time. Jan 11 14:12:07 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:07 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:08 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:08 music sudo[18577]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:08 music sudo[18579]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:08 music volumio[18349]: info: Shairport-Sync Started Jan 11 14:12:08 music volumio[18349]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:12:08 music volumio[18349]: info: Shairport-Sync Started Jan 11 14:12:08 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:12:08 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:12:08 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:08 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:08 music sudo[18581]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:08 music volumio[18349]: info: Shairport-Sync Started Jan 11 14:12:08 music go-librespot[18538]: time="2026-01-11T14:12:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:08 music go-librespot[18538]: time="2026-01-11T14:12:08-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:08 music go-librespot[18538]: time="2026-01-11T14:12:08-05:00" level=debug msg="completed challenge" Jan 11 14:12:08 music go-librespot[18538]: time="2026-01-11T14:12:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.255.62:80: connect: connection refused" Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=debug msg="completed challenge" Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:09 music mpd[18528]: 2026-01-11T14:12:09 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:12:09 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:12:09 music sudo[18489]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:09 music sudo[18479]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:09 music volumio[18349]: info: Completed starting Core Plugins Jan 11 14:12:09 music volumio[18349]: info: ------------------------------------------- Jan 11 14:12:09 music volumio[18349]: info: ----- MyVolumio plugins startup ---- Jan 11 14:12:09 music volumio[18349]: info: ------------------------------------------- Jan 11 14:12:09 music volumio[18349]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:12:09 music volumio[18349]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:12:09 music volumio[18349]: assert.ok(self.idling) Jan 11 14:12:09 music volumio[18349]: error: The expression evaluated to a falsy value: Jan 11 14:12:09 music volumio[18349]: assert.ok(self.idling) Jan 11 14:12:09 music volumio[18349]: error: updateQueue error: null Jan 11 14:12:09 music volumio[18349]: info: MPD running with PID18528 Jan 11 14:12:09 music volumio[18349]: ,establishing connection Jan 11 14:12:09 music volumio[18349]: error: updateQueue error: null Jan 11 14:12:09 music go-librespot[18538]: time="2026-01-11T14:12:09-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=debug msg="completed challenge" Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:10 music sudo[18622]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:12:10 music sudo[18622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:10 music sudo[18622]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:10 music sudo[18624]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:12:10 music sudo[18624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:10 music sudo[18624]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:10 music sudo[18626]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:12:10 music sudo[18626]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:10 music sudo[18626]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:10 music volumio[18349]: info: Upmpdcli Daemon Started Jan 11 14:12:10 music volumio[18349]: info: go-librespot daemon successfully initialized Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:10 music go-librespot[18538]: time="2026-01-11T14:12:10-05:00" level=debug msg="completed challenge" Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=debug msg="completed challenge" Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:11 music go-librespot[18538]: time="2026-01-11T14:12:11-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:11 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:11 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:12 music sudo[18631]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:12:12 music sudo[18631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:12 music sudo[18633]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:12:12 music sudo[18633]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:12 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:12:12 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:12:12 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:12:12 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:12:12 music sudo[18631]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:12 music mpd_monitor.sh[18636]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:12:12 music volumio[18349]: info: Successfully started MPD Monitor Jan 11 14:12:12 music sudo[18633]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:12 music volumio[18349]: info: Successfully started MPD Monitor Jan 11 14:12:13 music volumio[18349]: info: Initializing connection to go-librespot Websocket Jan 11 14:12:13 music volumio[18349]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:12:14 music volumio[18349]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:12:14 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:12:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:14 music go-librespot[18640]: go-librespot daemon starting... Jan 11 14:12:14 music go-librespot[18641]: time="2026-01-11T14:12:14-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:14 music go-librespot[18641]: time="2026-01-11T14:12:14-05:00" level=debug msg="app state loaded" Jan 11 14:12:14 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:14 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:14 music go-librespot[18641]: time="2026-01-11T14:12:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=info msg="zeroconf server listening on port 42409" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="obtained new client token: AACdpoRyQ0IYbuNXnAa3bHl/g2qJJj1nLM7ppUxOb/z9krvN8BrM1ngHW3t27QTRjM6gs9L+Gnwb3H2OlcsCBayTeSyoRkINAl4T479uw7KCATbwjKZpyNidigZo1fMvkFWj3Gb2I3FYGTxuL0q3YgHqJcFV7/StQbUEjQlwGLxhBzAWN62LafjRV+6LYaGQzlAxGfA+SSdjDQg9Fo/++59wJY7nLQk9Q2nu13bNXpz4XT7WdsIEStA=" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=debug msg="completed challenge" Jan 11 14:12:15 music go-librespot[18641]: time="2026-01-11T14:12:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="completed challenge" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:16 music volumio[18349]: info: Initializing connection to go-librespot Websocket Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="new websocket client" Jan 11 14:12:16 music volumio[18349]: info: Connection to go-librespot Websocket established Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=debug msg="completed challenge" Jan 11 14:12:16 music go-librespot[18641]: time="2026-01-11T14:12:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:17 music go-librespot[18641]: time="2026-01-11T14:12:17-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:12:17 music volumio[18349]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:12:17 music volumio[18349]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:12:18 music go-librespot[18641]: time="2026-01-11T14:12:18-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:18 music go-librespot[18641]: time="2026-01-11T14:12:18-05:00" level=debug msg="completed challenge" Jan 11 14:12:18 music go-librespot[18641]: time="2026-01-11T14:12:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:18 music volumio[18349]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:12:18 music volumio[18349]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:12:18 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:18 music volumio[18349]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:18 music volumio[18349]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:12:18 music volumio[18349]: info: MyVolumio login type: Token Jan 11 14:12:18 music volumio[18349]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:12:18 music volumio[18349]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:12:18 music go-librespot[18641]: time="2026-01-11T14:12:18-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:12:19 music go-librespot[18641]: time="2026-01-11T14:12:19-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:19 music go-librespot[18641]: time="2026-01-11T14:12:19-05:00" level=debug msg="completed challenge" Jan 11 14:12:19 music go-librespot[18641]: time="2026-01-11T14:12:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:19 music volumio[18349]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:12:19 music volumio[18349]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:12:19 music volumio[18349]: info: Streaming services startup Jan 11 14:12:19 music volumio[18349]: info: Starting Streaming Daemon Jan 11 14:12:19 music sudo[18651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:12:19 music sudo[18651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:19 music volumio[18349]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:12:19 music sudo[18651]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:19 music volumio[18349]: info: Getting Spotify volume Jan 11 14:12:19 music go-librespot[18641]: time="2026-01-11T14:12:19-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:19 music volumio[18349]: error: Cannot start Volumio Streaming Daemon Jan 11 14:12:19 music volumio[18349]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 11 14:12:19 music volumio[18349]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 11 14:12:20 music volumio[18349]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 11 14:12:20 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:20 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:20 music volumio[18349]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 11 14:12:20 music volumio[18349]: SPOTIFY: SPOTIFY VOLUME undefined Jan 11 14:12:20 music volumio[18349]: SPOTIFY: VOLUMIO VOLUME 86 Jan 11 14:12:20 music volumio[18349]: info: Aligning Spotify Volume to Volumio Volume Jan 11 14:12:20 music volumio[18349]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:20 music volumio[18349]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:20 music volumio[18349]: info: Setting Spotify Volume from Volumio: 86 Jan 11 14:12:20 music go-librespot[18641]: time="2026-01-11T14:12:20-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:20 music go-librespot[18641]: time="2026-01-11T14:12:20-05:00" level=debug msg="completed challenge" Jan 11 14:12:20 music go-librespot[18641]: time="2026-01-11T14:12:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:20 music go-librespot[18641]: time="2026-01-11T14:12:20-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:20 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:20 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:20 music volumio[18349]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:12:20 music volumio[18349]: Error: socket hang up Jan 11 14:12:20 music volumio[18349]: at connResetException (node:internal/errors:720:14) Jan 11 14:12:20 music volumio[18349]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 11 14:12:20 music volumio[18349]: at Socket.emit (node:events:526:35) Jan 11 14:12:20 music volumio[18349]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 11 14:12:20 music volumio[18349]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 11 14:12:20 music volumio[18349]: code: 'ECONNRESET', Jan 11 14:12:20 music volumio[18349]: response: undefined Jan 11 14:12:20 music volumio[18349]: } Jan 11 14:12:20 music volumio[18349]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:12:21 music sudo[18685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:11' Jan 11 14:12:21 music sudo[18685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:21 music sudo[18685]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:23 music volumio-remote-updater[22000]: [2026-01-11 14:12:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:12:23 music volumio-remote-updater[22000]: [2026-01-11 14:12:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:12:23 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:23 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:12:23 music systemd[1]: volumio.service: Consumed 26.926s CPU time. Jan 11 14:12:23 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:12:23 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:12:23 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:12:23 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:23 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:23 music go-librespot[18699]: go-librespot daemon starting... Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="app state loaded" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:23 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5257. Jan 11 14:12:23 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:12:23 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:12:23 music systemd[1]: volumio.service: Consumed 26.926s CPU time. Jan 11 14:12:23 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:12:23 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=info msg="zeroconf server listening on port 42041" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="obtained new client token: AACc22y+C5WBShhOa1HIK1UDdkVqUlGTIv2iLeewRlJ+6fM3x3hMIvk5hene/mLg+03vw87ZbsJJBk5Q/y45Zzz/4VGZZY9MJI9oQ939Eh/nW+yym9lyw6f7bILBjAQ8nflIWGukNTUqWOssGVC6gYgBCGnuUFttvXSFRNmlZexQbyrzWuMXQbvAM7AucOwx8A6xVvTs7msJaP4G6sA1dN/I17oG7auhRHmStrMFHLOHKNwrZzui5B0=" Jan 11 14:12:23 music go-librespot[18700]: time="2026-01-11T14:12:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=debug msg="completed challenge" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=debug msg="completed challenge" Jan 11 14:12:24 music go-librespot[18700]: time="2026-01-11T14:12:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:25 music go-librespot[18700]: time="2026-01-11T14:12:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:25 music go-librespot[18700]: time="2026-01-11T14:12:25-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:25 music go-librespot[18700]: time="2026-01-11T14:12:25-05:00" level=debug msg="completed challenge" Jan 11 14:12:25 music go-librespot[18700]: time="2026-01-11T14:12:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:25 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:25 music volumio[18709]: info: ----- Volumio3 ---- Jan 11 14:12:25 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:25 music volumio[18709]: info: ----- System startup ---- Jan 11 14:12:25 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:26 music go-librespot[18700]: time="2026-01-11T14:12:26-05: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" Jan 11 14:12:26 music go-librespot[18700]: time="2026-01-11T14:12:26-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:12:26 music volumio[18709]: info: MYVOLUMIO Environment detected Jan 11 14:12:26 music volumio[18709]: info: Plugin folders cleanup Jan 11 14:12:26 music volumio[18709]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:12:26 music volumio[18709]: info: Scanning category audio_interface Jan 11 14:12:26 music volumio[18709]: info: Scanning category miscellanea Jan 11 14:12:26 music volumio[18709]: info: Scanning category music_service Jan 11 14:12:26 music volumio[18709]: info: Scanning category plugins.json Jan 11 14:12:26 music volumio[18709]: info: Scanning category system_controller Jan 11 14:12:26 music volumio[18709]: info: Scanning category user_interface Jan 11 14:12:26 music volumio[18709]: info: Scanning into folder /data/plugins/ Jan 11 14:12:26 music volumio[18709]: info: Scanning category music_service Jan 11 14:12:26 music volumio[18709]: info: Plugin folders cleanup completed Jan 11 14:12:26 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:26 music volumio[18709]: info: ----- Core plugins startup ---- Jan 11 14:12:26 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:26 music volumio[18709]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:12:26 music volumio[18709]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:12:26 music volumio[18709]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:12:26 music volumio[18709]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:12:26 music volumio[18709]: info: Loading plugins from folder /data/plugins/ Jan 11 14:12:26 music volumio[18709]: info: Loading plugin "system"... Jan 11 14:12:26 music volumio[18709]: info: Loading plugin "appearance"... Jan 11 14:12:26 music go-librespot[18700]: time="2026-01-11T14:12:26-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:26 music go-librespot[18700]: time="2026-01-11T14:12:26-05:00" level=debug msg="completed challenge" Jan 11 14:12:26 music go-librespot[18700]: time="2026-01-11T14:12:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:27 music go-librespot[18700]: time="2026-01-11T14:12:27-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:27 music go-librespot[18700]: time="2026-01-11T14:12:27-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:27 music go-librespot[18700]: time="2026-01-11T14:12:27-05:00" level=debug msg="completed challenge" Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "network"... Jan 11 14:12:27 music volumio[18709]: info: Refreshing Cached IP Addresses Jan 11 14:12:27 music sudo[18738]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:12:27 music sudo[18738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:27 music go-librespot[18700]: time="2026-01-11T14:12:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:27 music sudo[18740]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:12:27 music sudo[18740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "services"... Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "alsa_controller"... Jan 11 14:12:27 music sudo[18740]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:27 music sudo[18738]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:27 music sudo[18747]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:12:27 music sudo[18747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:27 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "wizard"... Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "networkfs"... Jan 11 14:12:27 music volumio[18709]: info: Starting Udev Watcher for removable devices Jan 11 14:12:27 music volumio[18709]: info: Ignoring mount for partition: boot Jan 11 14:12:27 music volumio[18709]: info: Ignoring mount for partition: volumio Jan 11 14:12:27 music volumio[18709]: info: Ignoring mount for partition: volumio_data Jan 11 14:12:27 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "upnp"... Jan 11 14:12:27 music volumio[18709]: info: [1768158747845] Starting Upmpd Daemon Jan 11 14:12:27 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "my_music"... Jan 11 14:12:27 music volumio[18709]: info: Loading plugin "mpd"... Jan 11 14:12:28 music volumio[18709]: info: Loading plugin "upnp_browser"... Jan 11 14:12:28 music go-librespot[18700]: time="2026-01-11T14:12:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:28 music go-librespot[18700]: time="2026-01-11T14:12:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:28 music go-librespot[18700]: time="2026-01-11T14:12:28-05:00" level=debug msg="completed challenge" Jan 11 14:12:28 music volumio-remote-updater[22000]: [2026-01-11 14:12:28] [connect] Successful connection Jan 11 14:12:28 music sudo[18747]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:28 music go-librespot[18700]: time="2026-01-11T14:12:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:28 music go-librespot[18700]: time="2026-01-11T14:12:28-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:28 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:28 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:29 music volumio[18709]: info: Starting UPNP Browser Jan 11 14:12:29 music volumio[18709]: info: Loading plugin "alarm-clock"... Jan 11 14:12:29 music volumio[18709]: info: Loading plugin "airplay_emulation"... Jan 11 14:12:29 music volumio[18709]: info: Starting Shairport Sync Jan 11 14:12:29 music volumio[18709]: info: Loading plugin "last_100"... Jan 11 14:12:29 music volumio[18709]: info: Loading plugin "webradio"... Jan 11 14:12:30 music volumio[18709]: info: Loading plugin "i2s_dacs"... Jan 11 14:12:30 music volumio[18709]: info: I2S DAC not set, start Auto-detection Jan 11 14:12:30 music volumio[18709]: info: Loading plugin "volumiodiscovery"... Jan 11 14:12:30 music volumio[18709]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:30 music node[18709]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:30 music volumio[18709]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:30 music node[18709]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:30 music volumio[18709]: *** WARNING *** For more information see Jan 11 14:12:30 music node[18709]: *** WARNING *** For more information see Jan 11 14:12:30 music volumio[18709]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:30 music node[18709]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:30 music volumio[18709]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:30 music node[18709]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:30 music volumio[18709]: *** WARNING *** For more information see Jan 11 14:12:30 music node[18709]: *** WARNING *** For more information see Jan 11 14:12:30 music volumio[18709]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:12:30 music volumio[18709]: info: Discovery: Started advertising with name: music Jan 11 14:12:30 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:30 music volumio[18709]: info: Loading plugin "spop"... Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "outputs"... Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "albumart"... Jan 11 14:12:31 music volumio[18709]: info: Plugin example_plugin is not enabled Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "inputs"... Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "updater_comm"... Jan 11 14:12:31 music volumio[18709]: info: Plugin mpdemulation is not enabled Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "rest_api"... Jan 11 14:12:31 music volumio[18709]: info: Loading plugin "websocket"... Jan 11 14:12:31 music volumio[18709]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:12:31 music volumio[18709]: info: Loading i18n strings for locale en Jan 11 14:12:31 music volumio[18709]: Updating browse sources language Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:31 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:12:31 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::initPlayerControls Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:31 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:31 music go-librespot[18783]: go-librespot daemon starting... Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:31 music volumio[18709]: Express server listening on port 3000 Jan 11 14:12:31 music volumio[18709]: [Metrics] WebUI: 6s 567.37ms Jan 11 14:12:31 music go-librespot[18784]: time="2026-01-11T14:12:31-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:31 music go-librespot[18784]: time="2026-01-11T14:12:31-05:00" level=debug msg="app state loaded" Jan 11 14:12:31 music volumio[18709]: info: CoreStateMachine::resetVolumioState Jan 11 14:12:31 music volumio[18709]: info: CoreStateMachine::getcurrentVolume Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:31 music go-librespot[18784]: time="2026-01-11T14:12:31-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:31 music volumio[18709]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:12:31 music volumio-remote-updater[22000]: [2026-01-11 14:12:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768158748 101 Jan 11 14:12:31 music volumio[18773]: Forking 3 albumart workers Jan 11 14:12:31 music volumio[18709]: 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 Jan 11 14:12:31 music volumio[18709]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:31 music volumio[18709]: info: CoreStateMachine::pushState Jan 11 14:12:31 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:31 music volumio[18709]: info: CoreStateMachine::updateTrackBlock Jan 11 14:12:31 music volumio[18709]: info: CorePlayQueue::getTrackBlock Jan 11 14:12:31 music volumio[18709]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:32 music volumio[18709]: info: Reloading queue from file Jan 11 14:12:32 music volumio[18709]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:12:32 music volumio[18709]: info: CoreStateMachine::pushState Jan 11 14:12:32 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=info msg="zeroconf server listening on port 34211" Jan 11 14:12:32 music volumio[18709]: info: CoreStateMachine::setRandom null Jan 11 14:12:32 music volumio[18709]: info: CoreStateMachine::pushState Jan 11 14:12:32 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:32 music volumio[18709]: info: Setting Device type: Raspberry PI Jan 11 14:12:32 music volumio[18709]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:32 music volumio[18709]: info: CoreStateMachine::pushState Jan 11 14:12:32 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:32 music volumio[18709]: info: Completed loading Core Plugins Jan 11 14:12:32 music volumio[18709]: info: Preparing to generate the ALSA configuration file Jan 11 14:12:32 music volumio[18709]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:32 music volumio[18709]: info: Discovery: Found device music Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:32 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="obtained new client token: AAB8jTgaCNV1SYeUP+utOKdRIFjelng2/BGJEaqiNai7uF3BZ0/Dy2kZSd+cnmbizn0aNwpyMdtDYhrZAarApdQCCdrilLZ6s6fQEFUV5IIBy1i6Ec0wsg3qPF9CXm0A1eCQfhCR457fnmpNlKlMEGtOnAEBij752sN1OuabfaM65HvzEv3m1uATCqiiciFo1ypfBpJBErIfMlu2C0pWRsX7suWb8m8Hht6VaNpF1DXextkNE/dn" Jan 11 14:12:32 music volumio[18709]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:32 music volumio[18709]: info: Discovery: Found device music Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:32 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:32 music volumio[18709]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:12:32 music volumio[18709]: info: Output device has changed, restarting MPD Jan 11 14:12:32 music volumio[18709]: info: Output device has changed, restarting Shairport Sync Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:32 music sudo[18839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:32 music sudo[18839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:32 music sudo[18837]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:32 music sudo[18837]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:32 music sudo[18837]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:32 music volumio[18709]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:32 music volumio[18709]: info: ___________ START PLUGINS ___________ Jan 11 14:12:32 music volumio[18709]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:12:32 music volumio[18709]: info: Creating MPD Configuration file Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=debug msg="completed challenge" Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:32 music volumio[18709]: info: [1768158752438] CoreMusicLibrary::Adding element Media Servers Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:32 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:12:32 music volumio[18709]: info: UPNP Browser: Client initialized successfully Jan 11 14:12:32 music go-librespot[18784]: time="2026-01-11T14:12:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:32 music sudo[18849]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:32 music sudo[18847]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:32 music sudo[18849]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:32 music sudo[18847]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:32 music sudo[18847]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:32 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:32 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:32 music systemd[1]: mpd.service: Consumed 4.216s CPU time. Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:32 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:32 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:32 music volumio[18709]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:32 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:32 music volumio[18709]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:32 music volumio[18709]: info: [1768158752653] CoreMusicLibrary::Adding element Last_100 Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:32 music volumio[18709]: info: [1768158752657] CoreMusicLibrary::Adding element Webradio Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:32 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:32 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:32 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:32 music mpd_monitor.sh[18863]: MPD error: Connection reset by peer Jan 11 14:12:32 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:32 music mpd_monitor.sh[18636]: MPD Monitor Service: MPD Appears to be inactive, restarting Jan 11 14:12:32 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:32 music mpd_monitor.sh[18865]: mpd: no process found Jan 11 14:12:32 music volumio[18709]: info: Initializing BBC Radios Jan 11 14:12:32 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:32 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:32 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:32 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:32 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:32 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:32 music volumio[18709]: info: Creating Spotify config file Jan 11 14:12:32 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:33 music sudo[18879]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:12:33 music sudo[18879]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:12:33 music sudo[18879]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="completed challenge" Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:33 music volumio[18709]: info: Volumio Calling Home Jan 11 14:12:33 music volumio[18800]: Starting albumart workers Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=debug msg="completed challenge" Jan 11 14:12:33 music go-librespot[18784]: time="2026-01-11T14:12:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:34 music volumio[18798]: Starting albumart workers Jan 11 14:12:34 music volumio[18709]: info: MPD Permissions set Jan 11 14:12:34 music volumio[18709]: info: MPD Permissions set Jan 11 14:12:34 music volumio[18709]: info: Volumio called home Jan 11 14:12:34 music volumio[18709]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 11 14:12:34 music volumio[18797]: Starting albumart workers Jan 11 14:12:34 music volumio[18709]: info: Spotify config file written Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music sudo[18889]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:12:34 music sudo[18889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:12:34 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:12:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:34 music go-librespot[18896]: go-librespot daemon starting... Jan 11 14:12:34 music sudo[18889]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:34 music go-librespot[18897]: time="2026-01-11T14:12:34-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:34 music go-librespot[18897]: time="2026-01-11T14:12:34-05:00" level=debug msg="app state loaded" Jan 11 14:12:34 music go-librespot[18897]: time="2026-01-11T14:12:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:34 music volumio[18709]: info: No need to fix Spotify hosts Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=info msg="zeroconf server listening on port 44699" Jan 11 14:12:35 music volumio[18709]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:12:35 music volumio[18709]: info: Starting Shairport Sync Jan 11 14:12:35 music volumio[18709]: info: Starting Shairport Sync Jan 11 14:12:35 music volumio[18709]: info: Starting Shairport Sync Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="obtained new client token: AAAhmgmIidiPqNCIVmvZXRBkg1+Zssol4gAJN9DP6yLWQ9JZq8ZRuDaIsrJAOUNrk3A94sayy77DlaROXLFECDWzp92Qhr2RM2PHTnX3xDhsRk1UsSYSjq598u/5rl/FeqnREaSohuwwpr7Me6qMMCLoH4dWK3UyZhRA99Ex8vWqkhZWLjef4ciYhTI2exVqw1UpI8DtHVA0EGhFAeH08PsjjPHE4QUgXbCD5kHcSQqAGne8A1MR" Jan 11 14:12:35 music sudo[18918]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:35 music sudo[18918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:35 music sudo[18922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:35 music sudo[18922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Jan 11 14:12:35 music sudo[18920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:12:35 music sudo[18920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:35 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:35 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:35 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:12:35 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:12:35 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:35 music systemd[1]: shairport-sync.service: Consumed 1.885s CPU time. Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=debug msg="completed challenge" Jan 11 14:12:35 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:35 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:35 music volumio[18709]: info: Listing playlists Jan 11 14:12:35 music volumio[18709]: info: Listing playlists Jan 11 14:12:35 music go-librespot[18897]: time="2026-01-11T14:12:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:35 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:12:35 music sudo[18918]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:35 music volumio[18709]: info: Shairport-Sync Started Jan 11 14:12:35 music volumio[18709]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:12:35 music sudo[18922]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:35 music sudo[18920]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:35 music volumio[18709]: info: Shairport-Sync Started Jan 11 14:12:35 music volumio[18709]: info: Shairport-Sync Started Jan 11 14:12:36 music go-librespot[18897]: time="2026-01-11T14:12:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:36 music go-librespot[18897]: time="2026-01-11T14:12:36-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:36 music go-librespot[18897]: time="2026-01-11T14:12:36-05:00" level=debug msg="completed challenge" Jan 11 14:12:36 music go-librespot[18897]: time="2026-01-11T14:12:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:36 music go-librespot[18897]: time="2026-01-11T14:12:36-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 11 14:12:37 music go-librespot[18897]: time="2026-01-11T14:12:37-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:37 music go-librespot[18897]: time="2026-01-11T14:12:37-05:00" level=debug msg="completed challenge" Jan 11 14:12:37 music mpd[18884]: 2026-01-11T14:12:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:12:37 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:12:37 music mpd_monitor.sh[18636]: MPD Monitor Service: MPD restarted due to no mpc output. Jan 11 14:12:37 music sudo[18849]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:37 music sudo[18839]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:37 music volumio[18709]: info: Completed starting Core Plugins Jan 11 14:12:37 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:37 music volumio[18709]: info: ----- MyVolumio plugins startup ---- Jan 11 14:12:37 music volumio[18709]: info: ------------------------------------------- Jan 11 14:12:37 music volumio[18709]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:12:37 music volumio[18709]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:12:37 music volumio[18709]: assert.ok(self.idling) Jan 11 14:12:37 music volumio[18709]: error: The expression evaluated to a falsy value: Jan 11 14:12:37 music volumio[18709]: assert.ok(self.idling) Jan 11 14:12:37 music volumio[18709]: error: updateQueue error: null Jan 11 14:12:37 music volumio[18709]: info: MPD running with PID18884 Jan 11 14:12:37 music volumio[18709]: ,establishing connection Jan 11 14:12:37 music volumio[18709]: error: updateQueue error: null Jan 11 14:12:37 music go-librespot[18897]: time="2026-01-11T14:12:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:37 music sudo[18974]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:12:37 music sudo[18974]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:37 music sudo[18974]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:37 music sudo[18976]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:12:37 music sudo[18976]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:37 music sudo[18976]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:37 music sudo[18979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:12:37 music sudo[18979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:37 music sudo[18979]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:37 music volumio[18709]: info: Upmpdcli Daemon Started Jan 11 14:12:38 music volumio[18709]: info: go-librespot daemon successfully initialized Jan 11 14:12:38 music go-librespot[18897]: time="2026-01-11T14:12:38-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:12:38 music go-librespot[18897]: time="2026-01-11T14:12:38-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:38 music go-librespot[18897]: time="2026-01-11T14:12:38-05:00" level=debug msg="completed challenge" Jan 11 14:12:38 music go-librespot[18897]: time="2026-01-11T14:12:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="completed challenge" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=debug msg="completed challenge" Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:39 music go-librespot[18897]: time="2026-01-11T14:12:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:40 music sudo[18983]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:12:40 music sudo[18983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:40 music sudo[18985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:12:40 music sudo[18985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:40 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:12:40 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:12:40 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:12:40 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:12:40 music sudo[18985]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:40 music sudo[18983]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:40 music mpd_monitor.sh[18988]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:12:40 music volumio[18709]: info: Successfully started MPD Monitor Jan 11 14:12:40 music volumio[18709]: info: Successfully started MPD Monitor Jan 11 14:12:41 music volumio[18709]: info: Initializing connection to go-librespot Websocket Jan 11 14:12:41 music volumio[18709]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:12:42 music volumio[18709]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:12:43 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:12:43 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:43 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:43 music go-librespot[18992]: go-librespot daemon starting... Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="app state loaded" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=info msg="zeroconf server listening on port 45199" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="obtained new client token: AACmy/GMBkXiwG4frSXK7O1eI663J4qW4ePR77i3Qwam4L/zGb9M2bMpuZcm4j/IUNB08qi8D0rhIqu0N1b6QOvejuHX7QwdKqC+cndY1iii4WSpmFVg6sIkMOkdOW9JX4QCTgkZRNP36OfjkinsmFOavnpn5a2IB4FpEsTHMu5r11Js9PqfcJ4j6/RWsSYKAM7F//7qAPEXvNJX5J3fCSwYlrmo62zaSi0ERJuwQupdYkC+UI54b8E=" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=debug msg="completed challenge" Jan 11 14:12:43 music go-librespot[18993]: time="2026-01-11T14:12:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:44 music volumio[18709]: info: Initializing connection to go-librespot Websocket Jan 11 14:12:44 music go-librespot[18993]: time="2026-01-11T14:12:44-05:00" level=debug msg="new websocket client" Jan 11 14:12:44 music volumio[18709]: info: Connection to go-librespot Websocket established Jan 11 14:12:44 music go-librespot[18993]: time="2026-01-11T14:12:44-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:44 music go-librespot[18993]: time="2026-01-11T14:12:44-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:44 music go-librespot[18993]: time="2026-01-11T14:12:44-05:00" level=debug msg="completed challenge" Jan 11 14:12:44 music go-librespot[18993]: time="2026-01-11T14:12:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:44 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:44 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="completed challenge" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:12:45 music volumio[18709]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:12:45 music volumio[18709]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=debug msg="completed challenge" Jan 11 14:12:45 music go-librespot[18993]: time="2026-01-11T14:12:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:46 music volumio[18709]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:12:46 music volumio[18709]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:12:46 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:46 music volumio[18709]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:46 music volumio[18709]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:12:46 music volumio[18709]: info: MyVolumio login type: Token Jan 11 14:12:46 music volumio[18709]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:12:46 music volumio[18709]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:12:47 music volumio[18709]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:12:47 music volumio[18709]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:12:47 music volumio[18709]: info: Streaming services startup Jan 11 14:12:47 music volumio[18709]: info: Starting Streaming Daemon Jan 11 14:12:47 music sudo[19003]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:12:47 music sudo[19003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:47 music volumio[18709]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:12:47 music go-librespot[18993]: time="2026-01-11T14:12:47-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:12:47 music sudo[19003]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:47 music volumio[18709]: info: Getting Spotify volume Jan 11 14:12:47 music volumio[18709]: error: Cannot start Volumio Streaming Daemon Jan 11 14:12:47 music volumio[18709]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 11 14:12:47 music volumio[18709]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 11 14:12:47 music volumio[18709]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 11 14:12:47 music go-librespot[18993]: time="2026-01-11T14:12:47-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:47 music go-librespot[18993]: time="2026-01-11T14:12:47-05:00" level=debug msg="completed challenge" Jan 11 14:12:47 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:47 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:47 music volumio[18709]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 11 14:12:47 music volumio[18709]: SPOTIFY: SPOTIFY VOLUME undefined Jan 11 14:12:47 music volumio[18709]: SPOTIFY: VOLUMIO VOLUME 86 Jan 11 14:12:47 music volumio[18709]: info: Aligning Spotify Volume to Volumio Volume Jan 11 14:12:47 music volumio[18709]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:47 music volumio[18709]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:47 music volumio[18709]: info: Setting Spotify Volume from Volumio: 86 Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:48 music volumio[18709]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 11 14:12:48 music volumio[18709]: info: MyVolumio token set successfully Jan 11 14:12:48 music volumio[18709]: info: MYVOLUMIO: Adding device Jan 11 14:12:48 music volumio[18709]: info: MYVOLUMIO: Evaluating Server Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:12:48 music volumio[18709]: info: MyVolumio status changed Jan 11 14:12:48 music volumio[18709]: info: Streaming services startup Jan 11 14:12:48 music volumio[18709]: info: Starting Streaming Daemon Jan 11 14:12:48 music volumio[18709]: info: Removing browser output: myVolumio user plan is not superstar Jan 11 14:12:48 music volumio[18709]: info: Removing audio output: Jan 11 14:12:48 music volumio[18709]: info: Stoppping Tunnel 1 Jan 11 14:12:48 music sudo[19045]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:12:48 music sudo[19045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:48 music sudo[19045]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=debug msg="completed challenge" Jan 11 14:12:48 music volumio[18709]: error: Cannot start Volumio Streaming Daemon Jan 11 14:12:48 music volumio[18709]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 11 14:12:48 music volumio[18709]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 11 14:12:48 music sudo[19048]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jan 11 14:12:48 music sudo[19048]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 11 14:12:48 music sudo[19048]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:48 music volumio[18709]: info: Remote SSH Stopped Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:48 music go-librespot[18993]: time="2026-01-11T14:12:48-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:48 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:48 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:48 music volumio[18709]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:12:48 music volumio[18709]: Error: socket hang up Jan 11 14:12:48 music volumio[18709]: at connResetException (node:internal/errors:720:14) Jan 11 14:12:48 music volumio[18709]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 11 14:12:48 music volumio[18709]: at Socket.emit (node:events:526:35) Jan 11 14:12:48 music volumio[18709]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 11 14:12:48 music volumio[18709]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 11 14:12:48 music volumio[18709]: code: 'ECONNRESET', Jan 11 14:12:48 music volumio[18709]: response: undefined Jan 11 14:12:48 music volumio[18709]: } Jan 11 14:12:48 music volumio[18709]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:12:49 music sudo[19064]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:11' Jan 11 14:12:49 music sudo[19064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:49 music sudo[19064]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:50 music volumio-remote-updater[22000]: [2026-01-11 14:12:50] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:12:50 music volumio-remote-updater[22000]: [2026-01-11 14:12:50] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:12:50 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:50 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:12:50 music systemd[1]: volumio.service: Consumed 27.568s CPU time. Jan 11 14:12:50 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:12:50 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:12:50 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5258. Jan 11 14:12:50 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:12:50 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:12:50 music systemd[1]: volumio.service: Consumed 27.568s CPU time. Jan 11 14:12:50 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:12:50 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:12:52 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:12:52 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:52 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:12:52 music go-librespot[19091]: go-librespot daemon starting... Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="app state loaded" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:12:52 music volumio[19076]: info: ------------------------------------------- Jan 11 14:12:52 music volumio[19076]: info: ----- Volumio3 ---- Jan 11 14:12:52 music volumio[19076]: info: ------------------------------------------- Jan 11 14:12:52 music volumio[19076]: info: ----- System startup ---- Jan 11 14:12:52 music volumio[19076]: info: ------------------------------------------- Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=info msg="zeroconf server listening on port 38861" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="obtained new client token: AABIOvfkRMf0YCm77OMMgxQl4B7ApqmDmXSlB9WCwBn69RTr++xTF5kin9zC4aslu3lwU6nXbkrHNYrTDnQEwq6zTXRRbBggmcgPaGhoOXS24e+fLpCjXtDIue+q+8TQr5YtsYrSroFSqjvOC65avlkM8cMNzecUEZl493kLWfhCrZUNShfV27pxtkcpsij1gbuRa63SQCIlIIlTdZePBjHbZaqfEVr1AVMQVbD8ocwFvEow2VSML8c=" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=debug msg="completed challenge" Jan 11 14:12:52 music go-librespot[19092]: time="2026-01-11T14:12:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:53 music volumio[19076]: info: MYVOLUMIO Environment detected Jan 11 14:12:53 music volumio[19076]: info: Plugin folders cleanup Jan 11 14:12:53 music volumio[19076]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:12:53 music volumio[19076]: info: Scanning category audio_interface Jan 11 14:12:53 music volumio[19076]: info: Scanning category miscellanea Jan 11 14:12:53 music volumio[19076]: info: Scanning category music_service Jan 11 14:12:53 music volumio[19076]: info: Scanning category plugins.json Jan 11 14:12:53 music volumio[19076]: info: Scanning category system_controller Jan 11 14:12:53 music volumio[19076]: info: Scanning category user_interface Jan 11 14:12:53 music volumio[19076]: info: Scanning into folder /data/plugins/ Jan 11 14:12:53 music volumio[19076]: info: Scanning category music_service Jan 11 14:12:53 music volumio[19076]: info: Plugin folders cleanup completed Jan 11 14:12:53 music volumio[19076]: info: ------------------------------------------- Jan 11 14:12:53 music volumio[19076]: info: ----- Core plugins startup ---- Jan 11 14:12:53 music volumio[19076]: info: ------------------------------------------- Jan 11 14:12:53 music volumio[19076]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:12:53 music volumio[19076]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:12:53 music volumio[19076]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:12:53 music volumio[19076]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:12:53 music volumio[19076]: info: Loading plugins from folder /data/plugins/ Jan 11 14:12:53 music volumio[19076]: info: Loading plugin "system"... Jan 11 14:12:53 music volumio[19076]: info: Loading plugin "appearance"... Jan 11 14:12:53 music go-librespot[19092]: time="2026-01-11T14:12:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:53 music go-librespot[19092]: time="2026-01-11T14:12:53-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:53 music go-librespot[19092]: time="2026-01-11T14:12:53-05:00" level=debug msg="completed challenge" Jan 11 14:12:53 music go-librespot[19092]: time="2026-01-11T14:12:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:54 music go-librespot[19092]: time="2026-01-11T14:12:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:12:54 music go-librespot[19092]: time="2026-01-11T14:12:54-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:54 music go-librespot[19092]: time="2026-01-11T14:12:54-05:00" level=debug msg="completed challenge" Jan 11 14:12:54 music go-librespot[19092]: time="2026-01-11T14:12:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "network"... Jan 11 14:12:54 music volumio[19076]: info: Refreshing Cached IP Addresses Jan 11 14:12:54 music sudo[19114]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:12:54 music sudo[19114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:54 music sudo[19116]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:12:54 music sudo[19114]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:54 music sudo[19116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "services"... Jan 11 14:12:54 music sudo[19116]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "alsa_controller"... Jan 11 14:12:54 music sudo[19124]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:12:54 music sudo[19124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:54 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "wizard"... Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "networkfs"... Jan 11 14:12:54 music volumio[19076]: info: Starting Udev Watcher for removable devices Jan 11 14:12:54 music volumio[19076]: info: Ignoring mount for partition: boot Jan 11 14:12:54 music volumio[19076]: info: Ignoring mount for partition: volumio Jan 11 14:12:54 music volumio[19076]: info: Ignoring mount for partition: volumio_data Jan 11 14:12:54 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "upnp"... Jan 11 14:12:54 music volumio[19076]: info: [1768158774634] Starting Upmpd Daemon Jan 11 14:12:54 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "my_music"... Jan 11 14:12:54 music volumio[19076]: info: Loading plugin "mpd"... Jan 11 14:12:55 music go-librespot[19092]: time="2026-01-11T14:12:55-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 11 14:12:55 music volumio[19076]: info: Loading plugin "upnp_browser"... Jan 11 14:12:55 music volumio-remote-updater[22000]: [2026-01-11 14:12:55] [connect] Successful connection Jan 11 14:12:55 music sudo[19124]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:55 music go-librespot[19092]: time="2026-01-11T14:12:55-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:55 music go-librespot[19092]: time="2026-01-11T14:12:55-05:00" level=debug msg="completed challenge" Jan 11 14:12:55 music go-librespot[19092]: time="2026-01-11T14:12:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:56 music go-librespot[19092]: time="2026-01-11T14:12:56-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:12:56 music go-librespot[19092]: time="2026-01-11T14:12:56-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:56 music go-librespot[19092]: time="2026-01-11T14:12:56-05:00" level=debug msg="completed challenge" Jan 11 14:12:56 music go-librespot[19092]: time="2026-01-11T14:12:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:56 music volumio[19076]: info: Starting UPNP Browser Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "alarm-clock"... Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "airplay_emulation"... Jan 11 14:12:56 music volumio[19076]: info: Starting Shairport Sync Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "last_100"... Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "webradio"... Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "i2s_dacs"... Jan 11 14:12:56 music volumio[19076]: info: I2S DAC not set, start Auto-detection Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "volumiodiscovery"... Jan 11 14:12:56 music volumio[19076]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:56 music volumio[19076]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:56 music volumio[19076]: *** WARNING *** For more information see Jan 11 14:12:56 music volumio[19076]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:56 music volumio[19076]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:56 music volumio[19076]: *** WARNING *** For more information see Jan 11 14:12:56 music node[19076]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:56 music node[19076]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:56 music node[19076]: *** WARNING *** For more information see Jan 11 14:12:56 music node[19076]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:12:56 music node[19076]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:12:56 music node[19076]: *** WARNING *** For more information see Jan 11 14:12:56 music volumio[19076]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:12:56 music volumio[19076]: info: Discovery: Started advertising with name: music Jan 11 14:12:56 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:12:56 music volumio[19076]: info: Loading plugin "spop"... Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=debug msg="completed keyexchange" Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=debug msg="completed challenge" Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:57 music go-librespot[19092]: time="2026-01-11T14:12:57-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:12:57 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:12:57 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "outputs"... Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "albumart"... Jan 11 14:12:58 music volumio[19076]: info: Plugin example_plugin is not enabled Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "inputs"... Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "updater_comm"... Jan 11 14:12:58 music volumio[19076]: info: Plugin mpdemulation is not enabled Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "rest_api"... Jan 11 14:12:58 music volumio[19076]: info: Loading plugin "websocket"... Jan 11 14:12:58 music volumio[19076]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:12:58 music volumio[19076]: info: Loading i18n strings for locale en Jan 11 14:12:58 music volumio[19076]: Updating browse sources language Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::initPlayerControls Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:58 music volumio[19076]: Express server listening on port 3000 Jan 11 14:12:58 music volumio[19076]: [Metrics] WebUI: 6s 615.82ms Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::resetVolumioState Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::getcurrentVolume Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:58 music volumio[19076]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:12:58 music volumio[19076]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::pushState Jan 11 14:12:58 music volumio[19149]: Forking 3 albumart workers Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::updateTrackBlock Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrackBlock Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:58 music volumio-remote-updater[22000]: [2026-01-11 14:12:58] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768158775 101 Jan 11 14:12:58 music volumio[19076]: 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 Jan 11 14:12:58 music volumio[19076]: info: Reloading queue from file Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::pushState Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::setRandom null Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::pushState Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:58 music volumio[19076]: info: Setting Device type: Raspberry PI Jan 11 14:12:58 music volumio[19076]: info: Listing playlists Jan 11 14:12:58 music volumio[19076]: info: Listing playlists Jan 11 14:12:58 music volumio[19076]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:12:58 music volumio[19076]: info: CoreStateMachine::pushState Jan 11 14:12:58 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:58 music volumio[19076]: info: CoreCommandRouter::volumioPushState Jan 11 14:12:59 music volumio[19076]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:59 music volumio[19076]: info: Discovery: Found device music Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:59 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:59 music volumio[19076]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:12:59 music volumio[19076]: info: Discovery: Found device music Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::volumioGetState Jan 11 14:12:59 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:12:59 music volumio[19076]: info: Completed loading Core Plugins Jan 11 14:12:59 music volumio[19076]: info: Preparing to generate the ALSA configuration file Jan 11 14:12:59 music volumio[19076]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:12:59 music volumio[19076]: info: Output device has changed, restarting MPD Jan 11 14:12:59 music volumio[19076]: info: Output device has changed, restarting Shairport Sync Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:59 music sudo[19204]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:59 music sudo[19204]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:59 music sudo[19204]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:59 music sudo[19206]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:59 music sudo[19206]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:59 music volumio[19076]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:59 music volumio[19076]: info: ___________ START PLUGINS ___________ Jan 11 14:12:59 music volumio[19076]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:12:59 music volumio[19076]: info: Creating MPD Configuration file Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:59 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:12:59 music volumio[19076]: info: [1768158779259] CoreMusicLibrary::Adding element Media Servers Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:59 music sudo[19214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:12:59 music sudo[19214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:59 music sudo[19214]: pam_unix(sudo:session): session closed for user root Jan 11 14:12:59 music volumio[19076]: info: UPNP Browser: Client initialized successfully Jan 11 14:12:59 music sudo[19216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:12:59 music sudo[19216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:12:59 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:59 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:59 music systemd[1]: mpd.service: Consumed 4.105s CPU time. Jan 11 14:12:59 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:59 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:59 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:59 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:59 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:59 music volumio[19076]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:59 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:12:59 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:12:59 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:12:59 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:12:59 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:12:59 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:12:59 music volumio[19076]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:59 music volumio[19076]: info: [1768158779500] CoreMusicLibrary::Adding element Last_100 Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:59 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:12:59 music volumio[19076]: info: [1768158779506] CoreMusicLibrary::Adding element Webradio Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:59 music volumio[19076]: info: Initializing BBC Radios Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:12:59 music volumio[19076]: info: Creating Spotify config file Jan 11 14:12:59 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:12:59 music sudo[19230]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:12:59 music sudo[19230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:12:59 music sudo[19230]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:00 music volumio[19076]: info: Volumio Calling Home Jan 11 14:13:00 music volumio[19167]: Starting albumart workers Jan 11 14:13:00 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:13:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:00 music volumio[19165]: Starting albumart workers Jan 11 14:13:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:00 music go-librespot[19251]: go-librespot daemon starting... Jan 11 14:13:00 music go-librespot[19252]: time="2026-01-11T14:13:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:00 music volumio[19168]: Starting albumart workers Jan 11 14:13:01 music volumio[19076]: info: MPD Permissions set Jan 11 14:13:01 music volumio[19076]: info: MPD Permissions set Jan 11 14:13:01 music volumio[19076]: info: Volumio called home Jan 11 14:13:01 music volumio[19076]: info: Spotify config file written Jan 11 14:13:01 music go-librespot[19252]: time="2026-01-11T14:13:01-05:00" level=info msg="zeroconf server listening on port 44329" Jan 11 14:13:01 music sudo[19261]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:13:01 music sudo[19261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:01 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:13:01 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:13:01 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:01 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:01 music go-librespot[19264]: go-librespot daemon starting... Jan 11 14:13:01 music volumio[19076]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 11 14:13:01 music sudo[19261]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music go-librespot[19265]: time="2026-01-11T14:13:01-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:01 music go-librespot[19265]: time="2026-01-11T14:13:01-05:00" level=debug msg="app state loaded" Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music go-librespot[19265]: time="2026-01-11T14:13:01-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:01 music volumio[19076]: info: No need to fix Spotify hosts Jan 11 14:13:01 music volumio[19076]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:13:01 music volumio[19076]: info: Starting Shairport Sync Jan 11 14:13:01 music volumio[19076]: info: Starting Shairport Sync Jan 11 14:13:02 music sudo[19297]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:02 music sudo[19297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:02 music volumio[19076]: info: Starting Shairport Sync Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=info msg="zeroconf server listening on port 39151" Jan 11 14:13:02 music sudo[19305]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:02 music sudo[19305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:02 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:13:02 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:13:02 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:02 music sudo[19300]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:02 music systemd[1]: shairport-sync.service: Consumed 1.888s CPU time. Jan 11 14:13:02 music sudo[19300]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="obtained new client token: AAAgDDtbMTLJnCRfwGGdBP7QqVXDcGKor5zcoxLf9iEFxLNJ227I7gbbsHhwXWYDRlJoIZyANK5HMr/j8RHJ/EyzPSagcgJ4X7DjGmmgI5dd86JInqgd3uozl1muHrBgTG4S/LOP7F1nOMQKyReIcp+Vb7mDkjU3ZiF/6IDCt8e7tCSO0p12rEDPVx6K1CUGXGkJdBmnMh0uDVWObR2p8r/F46OoPjNuNdpy+6bbeeZVQCHNNggy" Jan 11 14:13:02 music volumio[19076]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:02 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:02 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:02 music sudo[19297]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:02 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:02 music volumio[19076]: info: Shairport-Sync Started Jan 11 14:13:02 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:13:02 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:02 music volumio[19076]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:13:02 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:02 music sudo[19305]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:02 music sudo[19300]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:02 music volumio[19076]: info: Shairport-Sync Started Jan 11 14:13:02 music volumio[19076]: info: Shairport-Sync Started Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=debug msg="completed challenge" Jan 11 14:13:02 music go-librespot[19265]: time="2026-01-11T14:13:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="completed challenge" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=debug msg="completed challenge" Jan 11 14:13:03 music go-librespot[19265]: time="2026-01-11T14:13:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:03 music mpd[19245]: 2026-01-11T14:13:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:13:03 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:13:03 music sudo[19216]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:03 music sudo[19206]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:03 music volumio[19076]: info: Completed starting Core Plugins Jan 11 14:13:03 music volumio[19076]: info: ------------------------------------------- Jan 11 14:13:03 music volumio[19076]: info: ----- MyVolumio plugins startup ---- Jan 11 14:13:03 music volumio[19076]: info: ------------------------------------------- Jan 11 14:13:03 music volumio[19076]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:13:04 music volumio[19076]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:13:04 music volumio[19076]: assert.ok(self.idling) Jan 11 14:13:04 music volumio[19076]: error: The expression evaluated to a falsy value: Jan 11 14:13:04 music volumio[19076]: assert.ok(self.idling) Jan 11 14:13:04 music volumio[19076]: info: MPD running with PID19245 Jan 11 14:13:04 music volumio[19076]: ,establishing connection Jan 11 14:13:04 music volumio[19076]: error: updateQueue error: null Jan 11 14:13:04 music volumio[19076]: error: updateQueue error: null Jan 11 14:13:04 music go-librespot[19265]: time="2026-01-11T14:13:04-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:13:04 music go-librespot[19265]: time="2026-01-11T14:13:04-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:04 music go-librespot[19265]: time="2026-01-11T14:13:04-05:00" level=debug msg="completed challenge" Jan 11 14:13:04 music go-librespot[19265]: time="2026-01-11T14:13:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:04 music sudo[19348]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:13:04 music sudo[19348]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:04 music sudo[19348]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:04 music sudo[19350]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:13:04 music sudo[19350]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:04 music sudo[19350]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:04 music sudo[19353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:13:04 music sudo[19353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:04 music sudo[19353]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:04 music volumio[19076]: info: Upmpdcli Daemon Started Jan 11 14:13:04 music volumio[19076]: info: go-librespot daemon successfully initialized Jan 11 14:13:04 music volumio[19076]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:04 music volumio[19076]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:05 music go-librespot[19265]: time="2026-01-11T14:13:05-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:13:05 music go-librespot[19265]: time="2026-01-11T14:13:05-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:05 music go-librespot[19265]: time="2026-01-11T14:13:05-05:00" level=debug msg="completed challenge" Jan 11 14:13:05 music go-librespot[19265]: time="2026-01-11T14:13:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:06 music go-librespot[19265]: time="2026-01-11T14:13:06-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 11 14:13:06 music go-librespot[19265]: time="2026-01-11T14:13:06-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:06 music go-librespot[19265]: time="2026-01-11T14:13:06-05:00" level=debug msg="completed challenge" Jan 11 14:13:06 music go-librespot[19265]: time="2026-01-11T14:13:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:06 music go-librespot[19265]: time="2026-01-11T14:13:06-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:06 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:06 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:13:06 music sudo[19357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:13:06 music sudo[19357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:06 music sudo[19359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:13:06 music sudo[19359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:07 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:13:07 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:13:07 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:13:07 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:13:07 music sudo[19357]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:07 music mpd_monitor.sh[19362]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:13:07 music volumio[19076]: info: Successfully started MPD Monitor Jan 11 14:13:07 music sudo[19359]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:07 music volumio[19076]: info: Successfully started MPD Monitor Jan 11 14:13:07 music volumio[19076]: info: Initializing connection to go-librespot Websocket Jan 11 14:13:07 music volumio[19076]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:13:08 music volumio[19076]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:13:09 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:13:09 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:09 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:09 music go-librespot[19366]: go-librespot daemon starting... Jan 11 14:13:09 music go-librespot[19367]: time="2026-01-11T14:13:09-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:09 music go-librespot[19367]: time="2026-01-11T14:13:09-05:00" level=debug msg="app state loaded" Jan 11 14:13:09 music go-librespot[19367]: time="2026-01-11T14:13:09-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=info msg="zeroconf server listening on port 34729" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="obtained new client token: AAB0eULN65liALWjPfzkWr0yWkj4x6oO2EJv/VLpddDso1E2v0KxbrEwLcGAsTZt+rz8f1CqOiBgrgdoO5gO4EXrjI3D8Lw3aKZLMT3xRMKCSQmpilqngRCUFadnVFhEk7yJFOTeSaKJSdFkdefPcmqZeQjhJfbFiiutfrQihJPVp+LCAL66t/PZWr0lgAA9RbvLKcP6kcz/a1rO5DVY9vh+MT0ElrbfqFj0ktOhE7xnnTldGCwqlzI=" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="completed challenge" Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:10 music volumio[19076]: info: Initializing connection to go-librespot Websocket Jan 11 14:13:10 music go-librespot[19367]: time="2026-01-11T14:13:10-05:00" level=debug msg="new websocket client" Jan 11 14:13:10 music volumio[19076]: info: Connection to go-librespot Websocket established Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="completed challenge" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=debug msg="completed challenge" Jan 11 14:13:11 music go-librespot[19367]: time="2026-01-11T14:13:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:13:12 music volumio[19076]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:13:12 music volumio[19076]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:13:12 music go-librespot[19367]: time="2026-01-11T14:13:12-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:13:12 music go-librespot[19367]: time="2026-01-11T14:13:12-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:12 music go-librespot[19367]: time="2026-01-11T14:13:12-05:00" level=debug msg="completed challenge" Jan 11 14:13:12 music go-librespot[19367]: time="2026-01-11T14:13:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:13 music go-librespot[19367]: time="2026-01-11T14:13:13-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:13:13 music volumio[19076]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:13:13 music volumio[19076]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:13:13 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:13 music volumio[19076]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:13 music volumio[19076]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:13:13 music volumio[19076]: info: MyVolumio login type: Token Jan 11 14:13:13 music volumio[19076]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:13:13 music volumio[19076]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:13:13 music go-librespot[19367]: time="2026-01-11T14:13:13-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:13 music go-librespot[19367]: time="2026-01-11T14:13:13-05:00" level=debug msg="completed challenge" Jan 11 14:13:13 music go-librespot[19367]: time="2026-01-11T14:13:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:14 music go-librespot[19367]: time="2026-01-11T14:13:14-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:13:14 music volumio[19076]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:13:14 music volumio[19076]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:13:14 music volumio[19076]: info: Streaming services startup Jan 11 14:13:14 music volumio[19076]: info: Starting Streaming Daemon Jan 11 14:13:14 music go-librespot[19367]: time="2026-01-11T14:13:14-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:14 music go-librespot[19367]: time="2026-01-11T14:13:14-05:00" level=debug msg="completed challenge" Jan 11 14:13:14 music sudo[19377]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:13:14 music sudo[19377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:14 music volumio[19076]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:13:14 music sudo[19377]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:14 music volumio[19076]: info: Getting Spotify volume Jan 11 14:13:14 music volumio[19076]: error: Cannot start Volumio Streaming Daemon Jan 11 14:13:14 music volumio[19076]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 11 14:13:14 music volumio[19076]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 11 14:13:14 music go-librespot[19367]: time="2026-01-11T14:13:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:14 music go-librespot[19367]: time="2026-01-11T14:13:14-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:14 music volumio[19076]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 11 14:13:14 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:14 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:13:14 music volumio[19076]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:13:14 music volumio[19076]: Error: socket hang up Jan 11 14:13:14 music volumio[19076]: at connResetException (node:internal/errors:720:14) Jan 11 14:13:14 music volumio[19076]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 11 14:13:14 music volumio[19076]: at Socket.emit (node:events:526:35) Jan 11 14:13:14 music volumio[19076]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 11 14:13:14 music volumio[19076]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 11 14:13:14 music volumio[19076]: code: 'ECONNRESET', Jan 11 14:13:14 music volumio[19076]: response: undefined Jan 11 14:13:14 music volumio[19076]: } Jan 11 14:13:14 music volumio[19076]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:13:15 music sudo[19412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:12' Jan 11 14:13:15 music sudo[19412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:15 music sudo[19412]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:15 music volumio-remote-updater[22000]: [2026-01-11 14:13:15] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 11 14:13:15 music volumio-remote-updater[22000]: [2026-01-11 14:13:15] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 11 14:13:15 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:15 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 11 14:13:15 music systemd[1]: volumio.service: Consumed 26.522s CPU time. Jan 11 14:13:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:13:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:13:15 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5259. Jan 11 14:13:15 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 11 14:13:15 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 11 14:13:15 music systemd[1]: volumio.service: Consumed 26.522s CPU time. Jan 11 14:13:15 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 11 14:13:15 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 11 14:13:17 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 11 14:13:17 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:17 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:17 music go-librespot[19439]: go-librespot daemon starting... Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=debug msg="app state loaded" Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:17 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:17 music volumio[19424]: info: ----- Volumio3 ---- Jan 11 14:13:17 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:17 music volumio[19424]: info: ----- System startup ---- Jan 11 14:13:17 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:13:17 music go-librespot[19440]: time="2026-01-11T14:13:17-05:00" level=info msg="zeroconf server listening on port 42795" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="obtained new client token: AACS9SlV4wX7EeEK0tFMG5KL05lsIRS6uGMaHWy/3a58wB8w8dKzvnuECE1Q+JKyD9rDfGLv3dtObPUTH5QaLW9FTHaQ1qGhMhLB0cyF4GxjFBZBE8csf5H9oT0pz1Zqdu9Izch7+Xywfalc7DoKPZN79CNAMkpjMkirTdbB9h7MpMH+Y4STp3yqLZeDobc7syWDhK2hL2IrJOSH6VWQysQwC82K96J19BlY+SUox32lknEsWgDB" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="completed challenge" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:18 music volumio[19424]: info: MYVOLUMIO Environment detected Jan 11 14:13:18 music volumio[19424]: info: Plugin folders cleanup Jan 11 14:13:18 music volumio[19424]: info: Scanning into folder /volumio/app/plugins/ Jan 11 14:13:18 music volumio[19424]: info: Scanning category audio_interface Jan 11 14:13:18 music volumio[19424]: info: Scanning category miscellanea Jan 11 14:13:18 music volumio[19424]: info: Scanning category music_service Jan 11 14:13:18 music volumio[19424]: info: Scanning category plugins.json Jan 11 14:13:18 music volumio[19424]: info: Scanning category system_controller Jan 11 14:13:18 music volumio[19424]: info: Scanning category user_interface Jan 11 14:13:18 music volumio[19424]: info: Scanning into folder /data/plugins/ Jan 11 14:13:18 music volumio[19424]: info: Scanning category music_service Jan 11 14:13:18 music volumio[19424]: info: Plugin folders cleanup completed Jan 11 14:13:18 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:18 music volumio[19424]: info: ----- Core plugins startup ---- Jan 11 14:13:18 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:18 music volumio[19424]: info: Loading plugins from folder /volumio/app/plugins/ Jan 11 14:13:18 music volumio[19424]: info: Adding plugin upnp to MyMusic Plugins Jan 11 14:13:18 music volumio[19424]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 11 14:13:18 music volumio[19424]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 11 14:13:18 music volumio[19424]: info: Loading plugins from folder /data/plugins/ Jan 11 14:13:18 music volumio[19424]: info: Loading plugin "system"... Jan 11 14:13:18 music volumio[19424]: info: Loading plugin "appearance"... Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:18 music go-librespot[19440]: time="2026-01-11T14:13:18-05:00" level=debug msg="completed challenge" Jan 11 14:13:19 music go-librespot[19440]: time="2026-01-11T14:13:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:19 music go-librespot[19440]: time="2026-01-11T14:13:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:13:19 music go-librespot[19440]: time="2026-01-11T14:13:19-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:19 music go-librespot[19440]: time="2026-01-11T14:13:19-05:00" level=debug msg="completed challenge" Jan 11 14:13:19 music go-librespot[19440]: time="2026-01-11T14:13:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:19 music volumio[19424]: info: Loading plugin "network"... Jan 11 14:13:19 music volumio[19424]: info: Refreshing Cached IP Addresses Jan 11 14:13:19 music sudo[19463]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:13:19 music sudo[19463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:19 music sudo[19465]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:13:19 music sudo[19465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:19 music sudo[19465]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:19 music sudo[19463]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:19 music volumio[19424]: info: Loading plugin "services"... Jan 11 14:13:19 music volumio[19424]: info: Loading plugin "alsa_controller"... Jan 11 14:13:19 music sudo[19475]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 11 14:13:19 music sudo[19475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:20 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "wizard"... Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "networkfs"... Jan 11 14:13:20 music volumio[19424]: info: Starting Udev Watcher for removable devices Jan 11 14:13:20 music volumio[19424]: info: Ignoring mount for partition: boot Jan 11 14:13:20 music volumio[19424]: info: Ignoring mount for partition: volumio Jan 11 14:13:20 music volumio[19424]: info: Ignoring mount for partition: volumio_data Jan 11 14:13:20 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "volumio_command_line_client"... Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "upnp"... Jan 11 14:13:20 music volumio[19424]: info: [1768158800134] Starting Upmpd Daemon Jan 11 14:13:20 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "my_music"... Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "mpd"... Jan 11 14:13:20 music go-librespot[19440]: time="2026-01-11T14:13:20-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 11 14:13:20 music volumio-remote-updater[22000]: [2026-01-11 14:13:20] [connect] Successful connection Jan 11 14:13:20 music volumio[19424]: info: Loading plugin "upnp_browser"... Jan 11 14:13:20 music sudo[19475]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:20 music go-librespot[19440]: time="2026-01-11T14:13:20-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:20 music go-librespot[19440]: time="2026-01-11T14:13:20-05:00" level=debug msg="completed challenge" Jan 11 14:13:21 music go-librespot[19440]: time="2026-01-11T14:13:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:21 music go-librespot[19440]: time="2026-01-11T14:13:21-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:13:21 music go-librespot[19440]: time="2026-01-11T14:13:21-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:21 music go-librespot[19440]: time="2026-01-11T14:13:21-05:00" level=debug msg="completed challenge" Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:22 music volumio[19424]: info: Starting UPNP Browser Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "alarm-clock"... Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "airplay_emulation"... Jan 11 14:13:22 music volumio[19424]: info: Starting Shairport Sync Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "last_100"... Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "webradio"... Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "i2s_dacs"... Jan 11 14:13:22 music volumio[19424]: info: I2S DAC not set, start Auto-detection Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "volumiodiscovery"... Jan 11 14:13:22 music volumio[19424]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:13:22 music volumio[19424]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:13:22 music volumio[19424]: *** WARNING *** For more information see Jan 11 14:13:22 music volumio[19424]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:13:22 music volumio[19424]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:13:22 music volumio[19424]: *** WARNING *** For more information see Jan 11 14:13:22 music node[19424]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 11 14:13:22 music node[19424]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:13:22 music node[19424]: *** WARNING *** For more information see Jan 11 14:13:22 music node[19424]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 11 14:13:22 music node[19424]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 11 14:13:22 music node[19424]: *** WARNING *** For more information see Jan 11 14:13:22 music volumio[19424]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 11 14:13:22 music volumio[19424]: info: Discovery: Started advertising with name: music Jan 11 14:13:22 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 11 14:13:22 music volumio[19424]: info: Loading plugin "spop"... Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=debug msg="completed challenge" Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:22 music go-librespot[19440]: time="2026-01-11T14:13:22-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:22 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:22 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "outputs"... Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "albumart"... Jan 11 14:13:23 music volumio[19424]: info: Plugin example_plugin is not enabled Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "inputs"... Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "updater_comm"... Jan 11 14:13:23 music volumio[19424]: info: Plugin mpdemulation is not enabled Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "rest_api"... Jan 11 14:13:23 music volumio[19424]: info: Loading plugin "websocket"... Jan 11 14:13:23 music volumio[19424]: info: Starting Socket.io Server version 1.7.4 Jan 11 14:13:23 music volumio[19424]: info: Loading i18n strings for locale en Jan 11 14:13:23 music volumio[19424]: Updating browse sources language Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::initPlayerControls Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:13:23 music volumio[19424]: Express server listening on port 3000 Jan 11 14:13:23 music volumio[19424]: [Metrics] WebUI: 6s 638.25ms Jan 11 14:13:23 music volumio[19424]: info: CoreStateMachine::resetVolumioState Jan 11 14:13:23 music volumio[19424]: info: CoreStateMachine::getcurrentVolume Jan 11 14:13:23 music volumio[19424]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: Volumio Network Manager: Network status updated: 1 Jan 11 14:13:24 music volumio-remote-updater[22000]: [2026-01-11 14:13:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768158800 101 Jan 11 14:13:24 music volumio[19424]: 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 Jan 11 14:13:24 music volumio[19424]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::pushState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:13:24 music volumio[19498]: Forking 3 albumart workers Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioPushState Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::updateTrackBlock Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrackBlock Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 14:13:24 music volumio[19424]: info: Reloading queue from file Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::setRepeat null single undefined Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::pushState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioPushState Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::setRandom null Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::pushState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioPushState Jan 11 14:13:24 music volumio[19424]: info: Setting Device type: Raspberry PI Jan 11 14:13:24 music volumio[19424]: info: VolumeController:: Volume=86 Mute =false Jan 11 14:13:24 music volumio[19424]: info: CoreStateMachine::pushState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioPushState Jan 11 14:13:24 music volumio[19424]: info: Completed loading Core Plugins Jan 11 14:13:24 music volumio[19424]: info: Preparing to generate the ALSA configuration file Jan 11 14:13:24 music volumio[19424]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:13:24 music volumio[19424]: info: Discovery: Found device music Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 11 14:13:24 music volumio[19424]: info: Discovery: Found device music Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:24 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:24 music volumio[19424]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:13:24 music volumio[19424]: info: Output device has changed, restarting MPD Jan 11 14:13:24 music volumio[19424]: info: Output device has changed, restarting Shairport Sync Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:13:24 music volumio[19424]: info: ___________ START PLUGINS ___________ Jan 11 14:13:24 music sudo[19555]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:13:24 music sudo[19553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:13:24 music sudo[19553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:24 music sudo[19553]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:24 music volumio[19424]: info: ControllerMpd::onStart: Initializing MPD Jan 11 14:13:24 music sudo[19555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:24 music volumio[19424]: info: Creating MPD Configuration file Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:13:24 music volumio[19424]: info: [1768158804573] CoreMusicLibrary::Adding element Media Servers Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:13:24 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 11 14:13:24 music sudo[19563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:13:24 music sudo[19563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:24 music volumio[19424]: info: UPNP Browser: Client initialized successfully Jan 11 14:13:24 music sudo[19565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:13:24 music sudo[19565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:24 music sudo[19563]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:24 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:13:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:13:24 music systemd[1]: mpd.service: Consumed 4.198s CPU time. Jan 11 14:13:24 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:13:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:13:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:13:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:13:24 music systemd[1]: mpd.service: Deactivated successfully. Jan 11 14:13:24 music volumio[19424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:13:24 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 11 14:13:24 music systemd[1]: mpd.socket: Deactivated successfully. Jan 11 14:13:24 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 11 14:13:24 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:13:24 music volumio[19424]: info: [1768158804789] CoreMusicLibrary::Adding element Last_100 Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 11 14:13:24 music volumio[19424]: info: [1768158804794] CoreMusicLibrary::Adding element Webradio Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:13:24 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 11 14:13:24 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:13:24 music volumio[19424]: info: Initializing BBC Radios Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:13:24 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:24 music volumio[19424]: info: Creating Spotify config file Jan 11 14:13:25 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:25 music sudo[19579]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:13:25 music sudo[19579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 11 14:13:25 music sudo[19579]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:25 music volumio[19424]: info: Volumio Calling Home Jan 11 14:13:26 music volumio[19424]: info: MPD Permissions set Jan 11 14:13:26 music volumio[19424]: info: MPD Permissions set Jan 11 14:13:26 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 11 14:13:26 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:26 music volumio[19514]: Starting albumart workers Jan 11 14:13:26 music volumio[19424]: info: Volumio called home Jan 11 14:13:26 music volumio[19424]: info: Spotify config file written Jan 11 14:13:26 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:26 music go-librespot[19598]: go-librespot daemon starting... Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:26 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:26 music go-librespot[19601]: time="2026-01-11T14:13:26-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:26 music go-librespot[19601]: time="2026-01-11T14:13:26-05:00" level=debug msg="app state loaded" Jan 11 14:13:26 music go-librespot[19601]: time="2026-01-11T14:13:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:26 music volumio[19519]: Starting albumart workers Jan 11 14:13:26 music sudo[19600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 11 14:13:26 music sudo[19600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:26 music volumio[19424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 11 14:13:26 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 11 14:13:26 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:26 music volumio[19515]: Starting albumart workers Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:26 music go-librespot[19612]: go-librespot daemon starting... Jan 11 14:13:26 music sudo[19600]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:13:26 music volumio[19424]: info: No need to fix Spotify hosts Jan 11 14:13:26 music go-librespot[19617]: time="2026-01-11T14:13:26-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:26 music go-librespot[19617]: time="2026-01-11T14:13:26-05:00" level=debug msg="app state loaded" Jan 11 14:13:26 music go-librespot[19617]: time="2026-01-11T14:13:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=info msg="zeroconf server listening on port 39153" Jan 11 14:13:27 music volumio[19424]: info: Listing playlists Jan 11 14:13:27 music volumio[19424]: info: Listing playlists Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="obtained new client token: AABHgPK39JFRnXg68tzwLyn1SV9+//Q10zLbtllwhsqjYIMr3PS+M7ZCr9vhcf4eMmvyQ4vxaF2zB2ovPEC4RBoR97TtCVYGTLie5VHvsR1Yrn6aS3NgtvhqWtMbzBYzu9pkGylilxcyEx5XvFTtMHlT7sysJm9BtHYAMrhvMJc4k3bmcrVBdYqnBkOil0BATPUPlg92093FCIinV578kSbCxS8uQKCO6dYUdKid/PqN6uzIGFbx" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:27 music volumio[19424]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=debug msg="completed challenge" Jan 11 14:13:27 music volumio[19424]: info: Starting Shairport Sync Jan 11 14:13:27 music volumio[19424]: info: Starting Shairport Sync Jan 11 14:13:27 music go-librespot[19617]: time="2026-01-11T14:13:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:27 music volumio[19424]: info: Starting Shairport Sync Jan 11 14:13:27 music sudo[19640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:27 music sudo[19640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:27 music sudo[19644]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:27 music sudo[19644]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:27 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:13:27 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:13:27 music sudo[19645]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:13:27 music sudo[19645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:27 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:27 music systemd[1]: shairport-sync.service: Consumed 1.883s CPU time. Jan 11 14:13:27 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:27 music sudo[19640]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:27 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 11 14:13:27 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 11 14:13:27 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:27 music volumio[19424]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:27 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:27 music volumio[19424]: info: Shairport-Sync Started Jan 11 14:13:27 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 11 14:13:27 music volumio[19424]: Error adding Membership: Error: addMembership EINVAL Jan 11 14:13:27 music sudo[19645]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:27 music sudo[19644]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:27 music volumio[19424]: info: Shairport-Sync Started Jan 11 14:13:27 music volumio[19424]: info: Shairport-Sync Started Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="completed challenge" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=debug msg="completed challenge" Jan 11 14:13:28 music go-librespot[19617]: time="2026-01-11T14:13:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:29 music mpd[19594]: 2026-01-11T14:13:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:13:29 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 11 14:13:29 music sudo[19565]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:29 music sudo[19555]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:29 music volumio[19424]: info: Completed starting Core Plugins Jan 11 14:13:29 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:29 music volumio[19424]: info: ----- MyVolumio plugins startup ---- Jan 11 14:13:29 music volumio[19424]: info: ------------------------------------------- Jan 11 14:13:29 music volumio[19424]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 11 14:13:29 music volumio[19424]: error: MPD error: The expression evaluated to a falsy value: Jan 11 14:13:29 music volumio[19424]: assert.ok(self.idling) Jan 11 14:13:29 music volumio[19424]: error: The expression evaluated to a falsy value: Jan 11 14:13:29 music volumio[19424]: assert.ok(self.idling) Jan 11 14:13:29 music volumio[19424]: error: updateQueue error: null Jan 11 14:13:29 music volumio[19424]: info: MPD running with PID19594 Jan 11 14:13:29 music volumio[19424]: ,establishing connection Jan 11 14:13:29 music volumio[19424]: error: updateQueue error: null Jan 11 14:13:29 music go-librespot[19617]: time="2026-01-11T14:13:29-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:13:29 music go-librespot[19617]: time="2026-01-11T14:13:29-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:29 music go-librespot[19617]: time="2026-01-11T14:13:29-05:00" level=debug msg="completed challenge" Jan 11 14:13:29 music go-librespot[19617]: time="2026-01-11T14:13:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:30 music sudo[19696]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 11 14:13:30 music sudo[19696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:30 music sudo[19696]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:30 music go-librespot[19617]: time="2026-01-11T14:13:30-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 11 14:13:30 music sudo[19698]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 11 14:13:30 music sudo[19698]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:30 music sudo[19698]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:30 music sudo[19700]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 11 14:13:30 music sudo[19700]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:30 music sudo[19700]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:30 music volumio[19424]: info: Upmpdcli Daemon Started Jan 11 14:13:30 music volumio[19424]: info: go-librespot daemon successfully initialized Jan 11 14:13:30 music go-librespot[19617]: time="2026-01-11T14:13:30-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:30 music go-librespot[19617]: time="2026-01-11T14:13:30-05:00" level=debug msg="completed challenge" Jan 11 14:13:30 music go-librespot[19617]: time="2026-01-11T14:13:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:31 music go-librespot[19617]: time="2026-01-11T14:13:31-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 11 14:13:31 music go-librespot[19617]: time="2026-01-11T14:13:31-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:31 music go-librespot[19617]: time="2026-01-11T14:13:31-05:00" level=debug msg="completed challenge" Jan 11 14:13:31 music go-librespot[19617]: time="2026-01-11T14:13:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:31 music go-librespot[19617]: time="2026-01-11T14:13:31-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:31 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:31 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:13:32 music sudo[19705]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:13:32 music sudo[19705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:32 music sudo[19707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 11 14:13:32 music sudo[19707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:32 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 11 14:13:32 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 11 14:13:32 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 11 14:13:32 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 11 14:13:32 music sudo[19707]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:32 music sudo[19705]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:32 music mpd_monitor.sh[19710]: MPD Monitor Service: Starting MPD Monitor Service Jan 11 14:13:32 music volumio[19424]: info: Successfully started MPD Monitor Jan 11 14:13:32 music volumio[19424]: info: Successfully started MPD Monitor Jan 11 14:13:33 music volumio[19424]: info: Initializing connection to go-librespot Websocket Jan 11 14:13:33 music volumio[19424]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:13:34 music volumio[19424]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 11 14:13:34 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 11 14:13:34 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:34 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 14:13:34 music go-librespot[19714]: go-librespot daemon starting... Jan 11 14:13:34 music go-librespot[19715]: time="2026-01-11T14:13:34-05:00" level=info msg="running go-librespot 0.6.2" Jan 11 14:13:34 music go-librespot[19715]: time="2026-01-11T14:13:34-05:00" level=debug msg="app state loaded" Jan 11 14:13:34 music go-librespot[19715]: time="2026-01-11T14:13:34-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 14:13:34 music volumio[19424]: info: CoreCommandRouter::volumioGetState Jan 11 14:13:34 music volumio[19424]: info: CorePlayQueue::getTrack 0 Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=info msg="zeroconf server listening on port 41831" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="obtained new client token: AABrjp9RnOHiZM+FuwYMxxkP1OdHXGff4q2zvZHwLLS3ZJYOriYpf9+st/Rl7nZeVOHZ+pPxgcobB15mtLosBwhFfY4XPw1TAVPY0sa/+Tz8heMMwgZYDYD9b33GUXdYZJeGAGdzXtLLoqzN/dbcFpfVSKNJPkMMryx7+maJuqCEEXYlmk3P24W+zU5ZPFGwhm/HdQ7PuWVWAkeAa7d7lLwh+ETbkUbfCYUI3L5jB6ph0SVM0LsuwQ4=" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=debug msg="completed challenge" Jan 11 14:13:35 music go-librespot[19715]: time="2026-01-11T14:13:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="completed challenge" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:36 music volumio[19424]: info: Initializing connection to go-librespot Websocket Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="new websocket client" Jan 11 14:13:36 music volumio[19424]: info: Connection to go-librespot Websocket established Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=debug msg="completed challenge" Jan 11 14:13:36 music go-librespot[19715]: time="2026-01-11T14:13:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 11 14:13:37 music volumio[19424]: info: Adding plugin bluetooth to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin multiroom to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin metavolumio to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin cd_controller to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 11 14:13:37 music volumio[19424]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 11 14:13:37 music go-librespot[19715]: time="2026-01-11T14:13:37-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 11 14:13:37 music go-librespot[19715]: time="2026-01-11T14:13:37-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:37 music go-librespot[19715]: time="2026-01-11T14:13:37-05:00" level=debug msg="completed challenge" Jan 11 14:13:38 music go-librespot[19715]: time="2026-01-11T14:13:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:38 music volumio[19424]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 11 14:13:38 music volumio[19424]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 11 14:13:38 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:38 music volumio[19424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:13:38 music volumio[19424]: info: Starting MyVolumio Remote Streaming Endpoints Jan 11 14:13:38 music volumio[19424]: info: MyVolumio login type: Token Jan 11 14:13:38 music go-librespot[19715]: time="2026-01-11T14:13:38-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 11 14:13:38 music volumio[19424]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 11 14:13:38 music volumio[19424]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 11 14:13:38 music go-librespot[19715]: time="2026-01-11T14:13:38-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:38 music go-librespot[19715]: time="2026-01-11T14:13:38-05:00" level=debug msg="completed challenge" Jan 11 14:13:38 music go-librespot[19715]: time="2026-01-11T14:13:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:39 music go-librespot[19715]: time="2026-01-11T14:13:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 11 14:13:39 music go-librespot[19715]: time="2026-01-11T14:13:39-05:00" level=debug msg="completed keyexchange" Jan 11 14:13:39 music go-librespot[19715]: time="2026-01-11T14:13:39-05:00" level=debug msg="completed challenge" Jan 11 14:13:39 music volumio[19424]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 11 14:13:39 music volumio[19424]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 11 14:13:39 music volumio[19424]: info: Streaming services startup Jan 11 14:13:39 music volumio[19424]: info: Starting Streaming Daemon Jan 11 14:13:39 music sudo[19725]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 11 14:13:39 music sudo[19725]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 11 14:13:39 music volumio[19424]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 11 14:13:39 music go-librespot[19715]: time="2026-01-11T14:13:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:39 music go-librespot[19715]: time="2026-01-11T14:13:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 11 14:13:39 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 14:13:39 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 14:13:39 music sudo[19725]: pam_unix(sudo:session): session closed for user root Jan 11 14:13:39 music volumio[19424]: info: Getting Spotify volume Jan 11 14:13:39 music volumio[19424]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:13:39 music volumio[19424]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 14:13:39 music volumio[19424]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 11 14:13:39 music volumio[19424]: errno: -111, Jan 11 14:13:39 music volumio[19424]: code: 'ECONNREFUSED', Jan 11 14:13:39 music volumio[19424]: syscall: 'connect', Jan 11 14:13:39 music volumio[19424]: address: '127.0.0.1', Jan 11 14:13:39 music volumio[19424]: port: 9879, Jan 11 14:13:39 music volumio[19424]: response: undefined Jan 11 14:13:39 music volumio[19424]: } Jan 11 14:13:39 music volumio[19424]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:13:40 music sudo[19759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 14:12' Jan 11 14:13:40 music sudo[19759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"