Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "outputs"... Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "albumart"... Jan 08 10:37:00 music volumio[22389]: info: Plugin example_plugin is not enabled Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "inputs"... Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "updater_comm"... Jan 08 10:37:00 music volumio[22389]: info: Plugin mpdemulation is not enabled Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "rest_api"... Jan 08 10:37:00 music volumio[22389]: info: Loading plugin "websocket"... Jan 08 10:37:00 music volumio[22389]: info: Starting Socket.io Server version 1.7.4 Jan 08 10:37:00 music volumio[22389]: info: Loading i18n strings for locale en Jan 08 10:37:00 music volumio[22389]: Updating browse sources language Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::initPlayerControls Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:00 music volumio[22389]: Express server listening on port 3000 Jan 08 10:37:00 music volumio[22389]: [Metrics] WebUI: 6s 582.62ms Jan 08 10:37:00 music volumio[22389]: info: CoreStateMachine::resetVolumioState Jan 08 10:37:00 music volumio[22389]: info: CoreStateMachine::getcurrentVolume Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:00 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:00 music volumio[22389]: info: Volumio Network Manager: Network status updated: 1 Jan 08 10:37:01 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 08 10:37:01 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:01 music volumio-remote-updater[696]: [2026-01-08 10:37:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767886617 101 Jan 08 10:37:01 music volumio[22452]: Forking 3 albumart workers Jan 08 10:37:01 music volumio[22389]: 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 08 10:37:01 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:01 music volumio[22389]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:01 music go-librespot[22468]: go-librespot daemon starting... Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::pushState Jan 08 10:37:01 music systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::updateTrackBlock Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrackBlock Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=debug msg="app state loaded" Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:01 music volumio[22389]: info: Reloading queue from file Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::setRepeat null single undefined Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::pushState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::setRandom null Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::pushState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:01 music volumio[22389]: info: Setting Device type: Raspberry PI Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-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 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-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 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-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 08 10:37:01 music volumio[22389]: info: Listing playlists Jan 08 10:37:01 music volumio[22389]: info: Listing playlists Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=info msg="zeroconf server listening on port 39117" Jan 08 10:37:01 music volumio[22389]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:01 music volumio[22389]: info: CoreStateMachine::pushState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:01 music volumio[22389]: info: Completed loading Core Plugins Jan 08 10:37:01 music volumio[22389]: info: Preparing to generate the ALSA configuration file Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=debug msg="obtained new client token: AAAwCwv0DcMEWzcmt87tBBoJWmI9PQGbNSs7OsKpbYHkde6aEhYRT8YCInuJXQ9NV49tBM815DZLz8RaJXkcKend9mrljqEf5SiMVMNmj6GXGWF2HzsasBLtaPh5LrZ6Oxz8n76a/geVuA+ULGmBpBL6OFCBh0HYeb/+BhJUx7Unx/6fzXmHpvMcm8YQSCz9x88uDhFCkD0SGoG/4M6Fl6hFjWKhfH/ewQ8wQNCT0TigGcvboCHA3fU=" Jan 08 10:37:01 music volumio[22389]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:01 music volumio[22389]: info: Discovery: Found device music Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:01 music volumio[22389]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:01 music volumio[22389]: info: Discovery: Found device music Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:01 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:01 music volumio[22389]: info: Asound.conf file unchanged, so no further update is needed Jan 08 10:37:01 music volumio[22389]: info: Output device has changed, restarting MPD Jan 08 10:37:01 music volumio[22389]: info: Output device has changed, restarting Shairport Sync Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:01 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:01 music go-librespot[22471]: time="2026-01-08T10:37:01-05:00" level=debug msg="completed challenge" Jan 08 10:37:01 music sudo[22539]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:02 music sudo[22539]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:02 music sudo[22535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:02 music sudo[22535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:02 music sudo[22535]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:02 music go-librespot[22471]: time="2026-01-08T10:37:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:02 music volumio[22389]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:02 music volumio[22389]: info: ___________ START PLUGINS ___________ Jan 08 10:37:02 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 10:37:02 music volumio[22389]: info: ControllerMpd::onStart: Initializing MPD Jan 08 10:37:02 music volumio[22389]: info: Creating MPD Configuration file Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:02 music volumio[22389]: info: [1767886622136] CoreMusicLibrary::Adding element Media Servers Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:02 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:02 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:02 music systemd[1]: mpd.service: Consumed 4.117s CPU time. Jan 08 10:37:02 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:02 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:02 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:02 music volumio[22389]: info: UPNP Browser: Client initialized successfully Jan 08 10:37:02 music sudo[22550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:02 music sudo[22550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:02 music sudo[22548]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:02 music sudo[22548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:02 music sudo[22548]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:02 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:02 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:02 music volumio[22389]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:02 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:02 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:02 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:02 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:02 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:02 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:02 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:02 music volumio[22389]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:02 music volumio[22389]: info: [1767886622396] CoreMusicLibrary::Adding element Last_100 Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:02 music volumio[22389]: info: [1767886622412] CoreMusicLibrary::Adding element Webradio Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:02 music volumio[22389]: info: Initializing BBC Radios Jan 08 10:37:02 music go-librespot[22471]: time="2026-01-08T10:37:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:02 music sudo[22569]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 10:37:02 music sudo[22569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 10:37:02 music sudo[22569]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:02 music go-librespot[22471]: time="2026-01-08T10:37:02-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:02 music go-librespot[22471]: time="2026-01-08T10:37:02-05:00" level=debug msg="completed challenge" Jan 08 10:37:02 music volumio[22389]: info: Creating Spotify config file Jan 08 10:37:02 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:02 music go-librespot[22471]: time="2026-01-08T10:37:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:03 music systemd[1]: setdatetime-helper.service: Deactivated successfully. Jan 08 10:37:03 music systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jan 08 10:37:03 music systemd[1]: setdatetime-helper.service: Consumed 1.301s CPU time. Jan 08 10:37:03 music volumio[22389]: info: Volumio Calling Home Jan 08 10:37:03 music go-librespot[22471]: time="2026-01-08T10:37:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:03 music go-librespot[22471]: time="2026-01-08T10:37:03-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:03 music go-librespot[22471]: time="2026-01-08T10:37:03-05:00" level=debug msg="completed challenge" Jan 08 10:37:03 music go-librespot[22471]: time="2026-01-08T10:37:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:03 music volumio[22472]: Starting albumart workers Jan 08 10:37:03 music volumio[22469]: Starting albumart workers Jan 08 10:37:03 music volumio[22479]: Starting albumart workers Jan 08 10:37:03 music volumio[22389]: info: MPD Permissions set Jan 08 10:37:03 music volumio[22389]: info: MPD Permissions set Jan 08 10:37:03 music volumio[22389]: info: Spotify config file written Jan 08 10:37:04 music volumio[22389]: 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 08 10:37:04 music go-librespot[22471]: time="2026-01-08T10:37:04-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:04 music volumio[22389]: info: Volumio called home Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music sudo[22593]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 10:37:04 music sudo[22593]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:04 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music systemd[1]: go-librespot-daemon.service: Killing process 22474 (go-librespot) with signal SIGKILL. Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:04 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:04 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:04 music volumio[22389]: info: No need to fix Spotify hosts Jan 08 10:37:04 music go-librespot[22602]: go-librespot daemon starting... Jan 08 10:37:04 music sudo[22593]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-05:00" level=debug msg="app state loaded" Jan 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-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 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-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 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-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 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-05:00" level=info msg="zeroconf server listening on port 44413" Jan 08 10:37:04 music go-librespot[22606]: time="2026-01-08T10:37:04-05:00" level=debug msg="obtained new client token: AAA4tcAXZXC2y8fy0+u0O7hb7Z3OZhcVWn1EoLEf3w6hj0NkkgSAezHrldfsyRU5vdGWyg95peKOOBK9DExLBxo23vtmslWTcak6FJaSyA7Gk4fSQE1aWDt0JnLpztBRGWpgkekE4Hvqcu5Dcs85sM/ZuxAxgfke8hkHzmIY/mkQICAmBg9S0YyOTF9PgZUUb+eNtoKPD205ab6TbAA8A4RnZmHdC57C8jOZgISB5NBzMwPMkYrjeHw=" Jan 08 10:37:04 music volumio[22389]: info: Starting Shairport Sync Jan 08 10:37:04 music volumio[22389]: info: Starting Shairport Sync Jan 08 10:37:04 music volumio[22389]: info: Starting Shairport Sync Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:05 music sudo[22635]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:05 music sudo[22635]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:05 music sudo[22637]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:05 music sudo[22637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:05 music sudo[22639]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:05 music sudo[22639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="completed challenge" Jan 08 10:37:05 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:05 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:05 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:05 music systemd[1]: shairport-sync.service: Consumed 1.876s CPU time. Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:05 music volumio[22389]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 08 10:37:05 music volumio[22389]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:05 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:05 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:05 music sudo[22635]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:05 music volumio[22389]: info: Shairport-Sync Started Jan 08 10:37:05 music volumio[22389]: Error adding Membership: Error: addMembership EINVAL Jan 08 10:37:05 music sudo[22637]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:05 music volumio[22389]: info: Shairport-Sync Started Jan 08 10:37:05 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:05 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:05 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:05 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:05 music volumio[22389]: info: Shairport-Sync Started Jan 08 10:37:05 music sudo[22639]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=debug msg="completed challenge" Jan 08 10:37:05 music go-librespot[22606]: time="2026-01-08T10:37:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:06 music go-librespot[22606]: time="2026-01-08T10:37:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:06 music go-librespot[22606]: time="2026-01-08T10:37:06-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:06 music go-librespot[22606]: time="2026-01-08T10:37:06-05:00" level=debug msg="completed challenge" Jan 08 10:37:06 music go-librespot[22606]: time="2026-01-08T10:37:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:06 music mpd[22584]: 2026-01-08T10:37:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 10:37:06 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 10:37:06 music sudo[22550]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:06 music sudo[22539]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:06 music volumio[22389]: info: Completed starting Core Plugins Jan 08 10:37:06 music volumio[22389]: info: ------------------------------------------- Jan 08 10:37:06 music volumio[22389]: info: ----- MyVolumio plugins startup ---- Jan 08 10:37:06 music volumio[22389]: info: ------------------------------------------- Jan 08 10:37:06 music volumio[22389]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 10:37:06 music volumio[22389]: error: MPD error: The expression evaluated to a falsy value: Jan 08 10:37:06 music volumio[22389]: assert.ok(self.idling) Jan 08 10:37:06 music volumio[22389]: error: The expression evaluated to a falsy value: Jan 08 10:37:06 music volumio[22389]: assert.ok(self.idling) Jan 08 10:37:06 music volumio[22389]: info: MPD running with PID22584 Jan 08 10:37:06 music volumio[22389]: ,establishing connection Jan 08 10:37:06 music volumio[22389]: error: updateQueue error: null Jan 08 10:37:06 music volumio[22389]: error: updateQueue error: null Jan 08 10:37:07 music sudo[22679]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:37:07 music sudo[22679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:07 music sudo[22681]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:37:07 music sudo[22681]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:07 music sudo[22679]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:07 music sudo[22681]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:07 music go-librespot[22606]: time="2026-01-08T10:37:07-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:07 music sudo[22685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 10:37:07 music sudo[22685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:07 music sudo[22685]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:07 music volumio[22389]: info: Upmpdcli Daemon Started Jan 08 10:37:07 music go-librespot[22606]: time="2026-01-08T10:37:07-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:07 music go-librespot[22606]: time="2026-01-08T10:37:07-05:00" level=debug msg="completed challenge" Jan 08 10:37:07 music go-librespot[22606]: time="2026-01-08T10:37:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:07 music volumio[22389]: info: go-librespot daemon successfully initialized Jan 08 10:37:07 music go-librespot[22606]: time="2026-01-08T10:37:07-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:37:08 music go-librespot[22606]: time="2026-01-08T10:37:08-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:08 music go-librespot[22606]: time="2026-01-08T10:37:08-05:00" level=debug msg="completed challenge" Jan 08 10:37:08 music go-librespot[22606]: time="2026-01-08T10:37:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:08 music go-librespot[22606]: time="2026-01-08T10:37:08-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:37:09 music go-librespot[22606]: time="2026-01-08T10:37:09-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:09 music go-librespot[22606]: time="2026-01-08T10:37:09-05:00" level=debug msg="completed challenge" Jan 08 10:37:09 music go-librespot[22606]: time="2026-01-08T10:37:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:09 music go-librespot[22606]: time="2026-01-08T10:37:09-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 08 10:37:09 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:09 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:09 music volumio[22389]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:09 music volumio[22389]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:09 music sudo[22692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:37:09 music sudo[22692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:09 music sudo[22694]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:37:09 music sudo[22694]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:09 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 10:37:09 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 10:37:09 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:10 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:10 music mpd_monitor.sh[22697]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 10:37:10 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 10:37:10 music sudo[22692]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:10 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 10:37:10 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:10 music volumio[22389]: info: Successfully started MPD Monitor Jan 08 10:37:10 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:10 music sudo[22694]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:10 music mpd_monitor.sh[22699]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 10:37:10 music volumio[22389]: info: Successfully started MPD Monitor Jan 08 10:37:10 music volumio[22389]: info: Initializing connection to go-librespot Websocket Jan 08 10:37:10 music volumio[22389]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:37:11 music volumio[22389]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 08 10:37:12 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 08 10:37:12 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:12 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:12 music go-librespot[22703]: go-librespot daemon starting... Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=debug msg="app state loaded" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-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 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-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 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-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 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=info msg="zeroconf server listening on port 34181" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=debug msg="obtained new client token: AADRu9fo/ThixTYBoPEF1ASuY2Iclp3V5pCGeTqlwVcRRSU02AP5DRkGX+1bIndilS32T5+iF3ZxceUzhLgKMpQC2I4hwEqnemTte891NXVpz0aHU0WuEVv6YE0Pwyen4Ziwpx1FtRjRkAXdi3kvs6ZSKAFTJfTUWi5B6IdmFLJZyyfYESLx2983ZOr5CAdXzPWZAiu7dVaNHiag1d/2+NdldbPkHhIiBoy4ns2Z2VUjVkUJ2jyt3s4=" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:12 music go-librespot[22704]: time="2026-01-08T10:37:12-05:00" level=debug msg="completed challenge" Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=debug msg="completed challenge" Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:13 music volumio[22389]: info: Initializing connection to go-librespot Websocket Jan 08 10:37:13 music go-librespot[22704]: time="2026-01-08T10:37:13-05:00" level=debug msg="new websocket client" Jan 08 10:37:13 music volumio[22389]: info: Connection to go-librespot Websocket established Jan 08 10:37:14 music go-librespot[22704]: time="2026-01-08T10:37:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:14 music go-librespot[22704]: time="2026-01-08T10:37:14-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:14 music go-librespot[22704]: time="2026-01-08T10:37:14-05:00" level=debug msg="completed challenge" Jan 08 10:37:14 music go-librespot[22704]: time="2026-01-08T10:37:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 08 10:37:15 music go-librespot[22704]: time="2026-01-08T10:37:15-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 08 10:37:15 music volumio[22389]: info: Adding plugin bluetooth to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin multiroom to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin metavolumio to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin cd_controller to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 08 10:37:15 music volumio[22389]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 08 10:37:15 music go-librespot[22704]: time="2026-01-08T10:37:15-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:15 music go-librespot[22704]: time="2026-01-08T10:37:15-05:00" level=debug msg="completed challenge" Jan 08 10:37:15 music go-librespot[22704]: time="2026-01-08T10:37:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:15 music go-librespot[22704]: time="2026-01-08T10:37:15-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 08 10:37:16 music go-librespot[22704]: time="2026-01-08T10:37:16-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:16 music go-librespot[22704]: time="2026-01-08T10:37:16-05:00" level=debug msg="completed challenge" Jan 08 10:37:16 music volumio[22389]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 08 10:37:16 music volumio[22389]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 08 10:37:16 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:16 music volumio[22389]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:16 music volumio[22389]: info: Starting MyVolumio Remote Streaming Endpoints Jan 08 10:37:16 music volumio[22389]: info: MyVolumio login type: Token Jan 08 10:37:16 music volumio[22389]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 08 10:37:16 music volumio[22389]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 08 10:37:16 music go-librespot[22704]: time="2026-01-08T10:37:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:16 music go-librespot[22704]: time="2026-01-08T10:37:16-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 08 10:37:17 music go-librespot[22704]: time="2026-01-08T10:37:17-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:17 music go-librespot[22704]: time="2026-01-08T10:37:17-05:00" level=debug msg="completed challenge" Jan 08 10:37:17 music volumio[22389]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 08 10:37:17 music volumio[22389]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 08 10:37:17 music volumio[22389]: info: Streaming services startup Jan 08 10:37:17 music volumio[22389]: info: Starting Streaming Daemon Jan 08 10:37:17 music sudo[22728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 08 10:37:17 music sudo[22728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:17 music volumio[22389]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 08 10:37:17 music go-librespot[22704]: time="2026-01-08T10:37:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:17 music go-librespot[22704]: time="2026-01-08T10:37:17-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 08 10:37:17 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:17 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:17 music sudo[22728]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:17 music volumio[22389]: info: Getting Spotify volume Jan 08 10:37:17 music volumio[22389]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:37:17 music volumio[22389]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:37:17 music volumio[22389]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 08 10:37:17 music volumio[22389]: errno: -111, Jan 08 10:37:17 music volumio[22389]: code: 'ECONNREFUSED', Jan 08 10:37:17 music volumio[22389]: syscall: 'connect', Jan 08 10:37:17 music volumio[22389]: address: '127.0.0.1', Jan 08 10:37:17 music volumio[22389]: port: 9879, Jan 08 10:37:17 music volumio[22389]: response: undefined Jan 08 10:37:17 music volumio[22389]: } Jan 08 10:37:17 music volumio[22389]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:37:18 music sudo[22749]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 10:36' Jan 08 10:37:18 music sudo[22749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:18 music sudo[22749]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:18 music volumio-remote-updater[696]: [2026-01-08 10:37:18] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 08 10:37:18 music volumio-remote-updater[696]: [2026-01-08 10:37:18] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 08 10:37:18 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:18 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 08 10:37:18 music systemd[1]: volumio.service: Consumed 26.526s CPU time. Jan 08 10:37:18 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:37:18 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:37:18 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 181. Jan 08 10:37:18 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:37:18 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 08 10:37:18 music systemd[1]: volumio.service: Consumed 26.526s CPU time. Jan 08 10:37:18 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 08 10:37:18 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:37:20 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 08 10:37:20 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:20 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:20 music go-librespot[22776]: go-librespot daemon starting... Jan 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-05:00" level=debug msg="app state loaded" Jan 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:20 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:20 music volumio[22761]: info: ----- Volumio3 ---- Jan 08 10:37:20 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:20 music volumio[22761]: info: ----- System startup ---- Jan 08 10:37:20 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-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 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-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 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-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 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-05:00" level=info msg="zeroconf server listening on port 44233" Jan 08 10:37:20 music go-librespot[22777]: time="2026-01-08T10:37:20-05:00" level=debug msg="obtained new client token: AAB2u3d6nVYsBUMKu+mHCVxXtBQbVlza4t/q/osfVl3V+OPnyysUUGyNG6te6Lc2sp+Rfxfh7B6H8hmK3g2vAEeUoBJURpV9v65Y4NDUSN1tRnU7CdN8199Kb29km0PfuZfGvwa2CzPDX+fTlHdtO3ELEYkyVBSxO+bqi97DdhsWbju5H3pOE3O4ewH7vAl49bHyOMpVCs5IjjVNQfIqL4470qhC6zJ+xArvLmkxdw+RoL93vPJHsTM=" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="completed challenge" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:21 music volumio[22761]: info: MYVOLUMIO Environment detected Jan 08 10:37:21 music volumio[22761]: info: Plugin folders cleanup Jan 08 10:37:21 music volumio[22761]: info: Scanning into folder /volumio/app/plugins/ Jan 08 10:37:21 music volumio[22761]: info: Scanning category audio_interface Jan 08 10:37:21 music volumio[22761]: info: Scanning category miscellanea Jan 08 10:37:21 music volumio[22761]: info: Scanning category music_service Jan 08 10:37:21 music volumio[22761]: info: Scanning category plugins.json Jan 08 10:37:21 music volumio[22761]: info: Scanning category system_controller Jan 08 10:37:21 music volumio[22761]: info: Scanning category user_interface Jan 08 10:37:21 music volumio[22761]: info: Scanning into folder /data/plugins/ Jan 08 10:37:21 music volumio[22761]: info: Scanning category music_service Jan 08 10:37:21 music volumio[22761]: info: Plugin folders cleanup completed Jan 08 10:37:21 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:21 music volumio[22761]: info: ----- Core plugins startup ---- Jan 08 10:37:21 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:21 music volumio[22761]: info: Loading plugins from folder /volumio/app/plugins/ Jan 08 10:37:21 music volumio[22761]: info: Adding plugin upnp to MyMusic Plugins Jan 08 10:37:21 music volumio[22761]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 08 10:37:21 music volumio[22761]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 08 10:37:21 music volumio[22761]: info: Loading plugins from folder /data/plugins/ Jan 08 10:37:21 music volumio[22761]: info: Loading plugin "system"... Jan 08 10:37:21 music volumio[22761]: info: Loading plugin "appearance"... Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-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 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=debug msg="completed challenge" Jan 08 10:37:21 music go-librespot[22777]: time="2026-01-08T10:37:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:22 music go-librespot[22777]: time="2026-01-08T10:37:22-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:22 music go-librespot[22777]: time="2026-01-08T10:37:22-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:22 music go-librespot[22777]: time="2026-01-08T10:37:22-05:00" level=debug msg="completed challenge" Jan 08 10:37:22 music go-librespot[22777]: time="2026-01-08T10:37:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "network"... Jan 08 10:37:22 music volumio[22761]: info: Refreshing Cached IP Addresses Jan 08 10:37:22 music sudo[22800]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:37:22 music sudo[22800]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:22 music sudo[22800]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:22 music sudo[22802]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:37:22 music sudo[22802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "services"... Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "alsa_controller"... Jan 08 10:37:22 music sudo[22802]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:22 music sudo[22810]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 08 10:37:22 music sudo[22810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:22 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "wizard"... Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "networkfs"... Jan 08 10:37:22 music volumio[22761]: info: Starting Udev Watcher for removable devices Jan 08 10:37:22 music volumio[22761]: info: Ignoring mount for partition: boot Jan 08 10:37:22 music volumio[22761]: info: Ignoring mount for partition: volumio Jan 08 10:37:22 music volumio[22761]: info: Ignoring mount for partition: volumio_data Jan 08 10:37:22 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "volumio_command_line_client"... Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "upnp"... Jan 08 10:37:22 music volumio[22761]: info: [1767886642916] Starting Upmpd Daemon Jan 08 10:37:22 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "my_music"... Jan 08 10:37:22 music volumio[22761]: info: Loading plugin "mpd"... Jan 08 10:37:23 music go-librespot[22777]: time="2026-01-08T10:37:23-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 08 10:37:23 music volumio[22761]: info: Loading plugin "upnp_browser"... Jan 08 10:37:23 music volumio-remote-updater[696]: [2026-01-08 10:37:23] [connect] Successful connection Jan 08 10:37:23 music sudo[22810]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:23 music go-librespot[22777]: time="2026-01-08T10:37:23-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:23 music go-librespot[22777]: time="2026-01-08T10:37:23-05:00" level=debug msg="completed challenge" Jan 08 10:37:23 music go-librespot[22777]: time="2026-01-08T10:37:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:24 music go-librespot[22777]: time="2026-01-08T10:37:24-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 08 10:37:24 music go-librespot[22777]: time="2026-01-08T10:37:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:24 music go-librespot[22777]: time="2026-01-08T10:37:24-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:24 music go-librespot[22777]: time="2026-01-08T10:37:24-05:00" level=debug msg="completed challenge" Jan 08 10:37:24 music go-librespot[22777]: time="2026-01-08T10:37:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:24 music volumio[22761]: info: Starting UPNP Browser Jan 08 10:37:24 music volumio[22761]: info: Loading plugin "alarm-clock"... Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "airplay_emulation"... Jan 08 10:37:25 music volumio[22761]: info: Starting Shairport Sync Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "last_100"... Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "webradio"... Jan 08 10:37:25 music go-librespot[22777]: time="2026-01-08T10:37:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:25 music go-librespot[22777]: time="2026-01-08T10:37:25-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:25 music go-librespot[22777]: time="2026-01-08T10:37:25-05:00" level=debug msg="completed challenge" Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "i2s_dacs"... Jan 08 10:37:25 music volumio[22761]: info: I2S DAC not set, start Auto-detection Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "volumiodiscovery"... Jan 08 10:37:25 music go-librespot[22777]: time="2026-01-08T10:37:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:25 music go-librespot[22777]: time="2026-01-08T10:37:25-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 08 10:37:25 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:25 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:25 music volumio[22761]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:25 music volumio[22761]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:25 music volumio[22761]: *** WARNING *** For more information see Jan 08 10:37:25 music volumio[22761]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:25 music volumio[22761]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:25 music volumio[22761]: *** WARNING *** For more information see Jan 08 10:37:25 music node[22761]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:25 music node[22761]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:25 music node[22761]: *** WARNING *** For more information see Jan 08 10:37:25 music node[22761]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:25 music node[22761]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:25 music node[22761]: *** WARNING *** For more information see Jan 08 10:37:25 music volumio[22761]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 08 10:37:25 music volumio[22761]: info: Discovery: Started advertising with name: music Jan 08 10:37:25 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:25 music volumio[22761]: info: Loading plugin "spop"... Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "outputs"... Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "albumart"... Jan 08 10:37:26 music volumio[22761]: info: Plugin example_plugin is not enabled Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "inputs"... Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "updater_comm"... Jan 08 10:37:26 music volumio[22761]: info: Plugin mpdemulation is not enabled Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "rest_api"... Jan 08 10:37:26 music volumio[22761]: info: Loading plugin "websocket"... Jan 08 10:37:26 music volumio[22761]: info: Starting Socket.io Server version 1.7.4 Jan 08 10:37:26 music volumio[22761]: info: Loading i18n strings for locale en Jan 08 10:37:26 music volumio[22761]: Updating browse sources language Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::initPlayerControls Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:26 music volumio[22761]: Express server listening on port 3000 Jan 08 10:37:26 music volumio[22761]: [Metrics] WebUI: 6s 692.02ms Jan 08 10:37:26 music volumio[22761]: info: CoreStateMachine::resetVolumioState Jan 08 10:37:26 music volumio[22761]: info: CoreStateMachine::getcurrentVolume Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:26 music volumio[22761]: info: Volumio Network Manager: Network status updated: 1 Jan 08 10:37:26 music volumio-remote-updater[696]: [2026-01-08 10:37:26] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767886643 101 Jan 08 10:37:26 music volumio[22835]: Forking 3 albumart workers Jan 08 10:37:26 music volumio[22761]: 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 08 10:37:26 music volumio[22761]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:26 music volumio[22761]: info: CoreStateMachine::pushState Jan 08 10:37:26 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:26 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::updateTrackBlock Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrackBlock Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:27 music volumio[22761]: info: Reloading queue from file Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::setRepeat null single undefined Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::pushState Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::setRandom null Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::pushState Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:27 music volumio[22761]: info: Setting Device type: Raspberry PI Jan 08 10:37:27 music volumio[22761]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:27 music volumio[22761]: info: CoreStateMachine::pushState Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:27 music volumio[22761]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:27 music volumio[22761]: info: Discovery: Found device music Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:27 music volumio[22761]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:27 music volumio[22761]: info: Discovery: Found device music Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:27 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:27 music volumio[22761]: info: Completed loading Core Plugins Jan 08 10:37:27 music volumio[22761]: info: Preparing to generate the ALSA configuration file Jan 08 10:37:27 music volumio[22761]: info: Asound.conf file unchanged, so no further update is needed Jan 08 10:37:27 music volumio[22761]: info: Output device has changed, restarting MPD Jan 08 10:37:27 music volumio[22761]: info: Output device has changed, restarting Shairport Sync Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:27 music sudo[22894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:27 music sudo[22892]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:27 music sudo[22894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:27 music sudo[22892]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:27 music volumio[22761]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:27 music volumio[22761]: info: ___________ START PLUGINS ___________ Jan 08 10:37:27 music sudo[22892]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:27 music volumio[22761]: info: ControllerMpd::onStart: Initializing MPD Jan 08 10:37:27 music volumio[22761]: info: Creating MPD Configuration file Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:27 music volumio[22761]: info: [1767886647436] CoreMusicLibrary::Adding element Media Servers Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:27 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 10:37:27 music volumio[22761]: info: UPNP Browser: Client initialized successfully Jan 08 10:37:27 music sudo[22902]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:27 music sudo[22902]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:27 music sudo[22904]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:27 music sudo[22904]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:27 music sudo[22902]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:27 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:27 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:27 music systemd[1]: mpd.service: Consumed 4.169s CPU time. Jan 08 10:37:27 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:27 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:27 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:27 music volumio[22761]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:27 music volumio[22761]: info: [1767886647583] CoreMusicLibrary::Adding element Last_100 Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:27 music volumio[22761]: info: [1767886647596] CoreMusicLibrary::Adding element Webradio Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:27 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:27 music volumio[22761]: info: Initializing BBC Radios Jan 08 10:37:27 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:27 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:27 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:27 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:27 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:27 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:27 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:27 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:27 music volumio[22761]: info: Creating Spotify config file Jan 08 10:37:27 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:27 music sudo[22931]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 10:37:27 music sudo[22931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 10:37:28 music sudo[22931]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:28 music volumio[22761]: info: Volumio Calling Home Jan 08 10:37:28 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 08 10:37:28 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:28 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:28 music go-librespot[22936]: go-librespot daemon starting... Jan 08 10:37:28 music go-librespot[22938]: time="2026-01-08T10:37:28-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:28 music volumio[22761]: info: MPD Permissions set Jan 08 10:37:28 music volumio[22761]: info: MPD Permissions set Jan 08 10:37:28 music volumio[22761]: info: Spotify config file written Jan 08 10:37:28 music volumio[22761]: 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 08 10:37:28 music volumio[22761]: info: Volumio called home Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:28 music sudo[22946]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 10:37:28 music sudo[22946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:29 music go-librespot[22938]: time="2026-01-08T10:37:29-05:00" level=info msg="zeroconf server listening on port 46155" Jan 08 10:37:29 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 08 10:37:29 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 08 10:37:29 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:29 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:29 music go-librespot[22955]: go-librespot daemon starting... Jan 08 10:37:29 music volumio[22761]: info: No need to fix Spotify hosts Jan 08 10:37:29 music sudo[22946]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=debug msg="app state loaded" Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:29 music volumio[22853]: Starting albumart workers Jan 08 10:37:29 music volumio[22852]: Starting albumart workers Jan 08 10:37:29 music volumio[22851]: Starting albumart workers Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-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 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-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 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-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 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=info msg="zeroconf server listening on port 34015" Jan 08 10:37:29 music volumio[22761]: info: Starting Shairport Sync Jan 08 10:37:29 music volumio[22761]: info: Starting Shairport Sync Jan 08 10:37:29 music volumio[22761]: info: Starting Shairport Sync Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=debug msg="obtained new client token: AAAOb0r/SfrRTrFnibR2LNgLIJDY6LDpnuY6nhsOPqVKdEelZefiFRQUvOxFlSYqsXTUKd2ymT/VwI1QvWBjgkyAmg2XLAI4E+xZBf1vFmIspx2QmQ7534w2uxBlOgQgEkhdxIKtk2UjabNqWzIfE+6RmkTwjYUNqdbeXUcJZ14TRypgd9iYz7NtKapIlB3z9WaA5TIVSStLTCkYV96Sb5Bx0Cwo7wSxRQrTRJzXuPGo1GVC4bZpiiA=" Jan 08 10:37:29 music sudo[22971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:29 music volumio[22761]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 08 10:37:29 music sudo[22971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:29 music sudo[22973]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:29 music go-librespot[22961]: time="2026-01-08T10:37:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:29 music sudo[22973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:29 music sudo[22975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:29 music sudo[22975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:29 music volumio[22761]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:29 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=debug msg="completed challenge" Jan 08 10:37:30 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:30 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:30 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:30 music systemd[1]: shairport-sync.service: Consumed 1.882s CPU time. Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:30 music volumio[22761]: info: Listing playlists Jan 08 10:37:30 music volumio[22761]: info: Listing playlists Jan 08 10:37:30 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:30 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:30 music sudo[22971]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:30 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:30 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:30 music sudo[22975]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:30 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:30 music sudo[22973]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:30 music volumio[22761]: info: Shairport-Sync Started Jan 08 10:37:30 music volumio[22761]: Error adding Membership: Error: addMembership EINVAL Jan 08 10:37:30 music volumio[22761]: info: Shairport-Sync Started Jan 08 10:37:30 music volumio[22761]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:30 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:30 music volumio[22761]: info: Shairport-Sync Started Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=debug msg="completed challenge" Jan 08 10:37:30 music go-librespot[22961]: time="2026-01-08T10:37:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:31 music go-librespot[22961]: time="2026-01-08T10:37:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:31 music go-librespot[22961]: time="2026-01-08T10:37:31-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:31 music go-librespot[22961]: time="2026-01-08T10:37:31-05:00" level=debug msg="completed challenge" Jan 08 10:37:31 music go-librespot[22961]: time="2026-01-08T10:37:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:32 music go-librespot[22961]: time="2026-01-08T10:37:32-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:32 music go-librespot[22961]: time="2026-01-08T10:37:32-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:32 music go-librespot[22961]: time="2026-01-08T10:37:32-05:00" level=debug msg="completed challenge" Jan 08 10:37:32 music go-librespot[22961]: time="2026-01-08T10:37:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:32 music mpd[22933]: 2026-01-08T10:37:32 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 10:37:32 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 10:37:32 music sudo[22904]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:32 music sudo[22894]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:32 music volumio[22761]: info: Completed starting Core Plugins Jan 08 10:37:32 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:32 music volumio[22761]: info: ----- MyVolumio plugins startup ---- Jan 08 10:37:32 music volumio[22761]: info: ------------------------------------------- Jan 08 10:37:32 music volumio[22761]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 10:37:32 music volumio[22761]: error: MPD error: The expression evaluated to a falsy value: Jan 08 10:37:32 music volumio[22761]: assert.ok(self.idling) Jan 08 10:37:32 music volumio[22761]: error: The expression evaluated to a falsy value: Jan 08 10:37:32 music volumio[22761]: assert.ok(self.idling) Jan 08 10:37:32 music volumio[22761]: error: updateQueue error: null Jan 08 10:37:32 music volumio[22761]: info: MPD running with PID22933 Jan 08 10:37:32 music volumio[22761]: ,establishing connection Jan 08 10:37:32 music volumio[22761]: error: updateQueue error: null Jan 08 10:37:32 music volumio[22761]: info: go-librespot daemon successfully initialized Jan 08 10:37:32 music go-librespot[22961]: time="2026-01-08T10:37:32-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 08 10:37:32 music sudo[23036]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:37:32 music sudo[23036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:32 music sudo[23038]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:37:32 music sudo[23036]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:32 music sudo[23038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:32 music sudo[23038]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:32 music sudo[23041]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 10:37:32 music sudo[23041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:33 music sudo[23041]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:33 music volumio[22761]: info: Upmpdcli Daemon Started Jan 08 10:37:33 music go-librespot[22961]: time="2026-01-08T10:37:33-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:33 music go-librespot[22961]: time="2026-01-08T10:37:33-05:00" level=debug msg="completed challenge" Jan 08 10:37:33 music go-librespot[22961]: time="2026-01-08T10:37:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:33 music go-librespot[22961]: time="2026-01-08T10:37:33-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 08 10:37:34 music go-librespot[22961]: time="2026-01-08T10:37:34-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:34 music go-librespot[22961]: time="2026-01-08T10:37:34-05:00" level=debug msg="completed challenge" Jan 08 10:37:34 music go-librespot[22961]: time="2026-01-08T10:37:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:34 music go-librespot[22961]: time="2026-01-08T10:37:34-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 08 10:37:34 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:34 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:35 music sudo[23047]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:37:35 music sudo[23047]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:35 music sudo[23049]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:37:35 music sudo[23049]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:35 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 10:37:35 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 10:37:35 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:35 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 10:37:35 music sudo[23047]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:35 music mpd_monitor.sh[23054]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 10:37:35 music volumio[22761]: info: Successfully started MPD Monitor Jan 08 10:37:35 music sudo[23049]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:35 music volumio[22761]: info: Successfully started MPD Monitor Jan 08 10:37:35 music volumio[22761]: info: Initializing connection to go-librespot Websocket Jan 08 10:37:35 music volumio[22761]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:37:37 music volumio[22761]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 08 10:37:37 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 08 10:37:37 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:37 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:37 music go-librespot[23058]: go-librespot daemon starting... Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=debug msg="app state loaded" Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-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 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-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 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-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 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=info msg="zeroconf server listening on port 35081" Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=debug msg="obtained new client token: AADvnrfq4ZoHM8whJ6japhJfvgy+RfZL+TeXDK8H+IMUuMx0y3pGMDfbLrKDttWtUxjqxnWTo29g6e7p/TcZsFDlfXuXGpB7Jn+1IGc2vvUf+PsMZ3bwVc9j18tvHHODsziDJ/WLZV0hurCvJlEMvJYREdU+0qDOscK0r7RbX2NDKXuAl1YQYeoE7ZWzrSk0W/v2v1LsKK7hThbRd542oBMh4Gc2VEGgjaGr0ThQQnfC8K6yQcZu6IE=" Jan 08 10:37:37 music go-librespot[23059]: time="2026-01-08T10:37:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="completed challenge" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:38 music volumio[22761]: info: Initializing connection to go-librespot Websocket Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="new websocket client" Jan 08 10:37:38 music volumio[22761]: info: Connection to go-librespot Websocket established Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=debug msg="completed challenge" Jan 08 10:37:38 music go-librespot[23059]: time="2026-01-08T10:37:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:39 music volumio[22761]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:39 music volumio[22761]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:39 music go-librespot[23059]: time="2026-01-08T10:37:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:39 music go-librespot[23059]: time="2026-01-08T10:37:39-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:39 music go-librespot[23059]: time="2026-01-08T10:37:39-05:00" level=debug msg="completed challenge" Jan 08 10:37:39 music go-librespot[23059]: time="2026-01-08T10:37:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=debug msg="completed challenge" Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 08 10:37:40 music volumio[22761]: info: Adding plugin bluetooth to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin multiroom to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin metavolumio to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin cd_controller to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 08 10:37:40 music volumio[22761]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:37:40 music go-librespot[23059]: time="2026-01-08T10:37:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 08 10:37:41 music volumio[22761]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 08 10:37:41 music go-librespot[23059]: time="2026-01-08T10:37:41-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:37:41 music volumio[22761]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 08 10:37:41 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:41 music volumio[22761]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:41 music volumio[22761]: info: Starting MyVolumio Remote Streaming Endpoints Jan 08 10:37:41 music volumio[22761]: info: MyVolumio login type: Token Jan 08 10:37:41 music volumio[22761]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 08 10:37:41 music volumio[22761]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 08 10:37:41 music go-librespot[23059]: time="2026-01-08T10:37:41-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:41 music go-librespot[23059]: time="2026-01-08T10:37:41-05:00" level=debug msg="completed challenge" Jan 08 10:37:41 music go-librespot[23059]: time="2026-01-08T10:37:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:41 music go-librespot[23059]: time="2026-01-08T10:37:41-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 08 10:37:41 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:41 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:42 music volumio[22761]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 08 10:37:42 music volumio[22761]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 08 10:37:42 music volumio[22761]: info: Streaming services startup Jan 08 10:37:42 music volumio[22761]: info: Starting Streaming Daemon Jan 08 10:37:42 music sudo[23070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 08 10:37:42 music sudo[23070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:42 music volumio[22761]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 08 10:37:42 music sudo[23070]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:42 music volumio[22761]: info: Getting Spotify volume Jan 08 10:37:42 music volumio[22761]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:37:42 music volumio[22761]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:37:42 music volumio[22761]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 08 10:37:42 music volumio[22761]: errno: -111, Jan 08 10:37:42 music volumio[22761]: code: 'ECONNREFUSED', Jan 08 10:37:42 music volumio[22761]: syscall: 'connect', Jan 08 10:37:42 music volumio[22761]: address: '127.0.0.1', Jan 08 10:37:42 music volumio[22761]: port: 9879, Jan 08 10:37:42 music volumio[22761]: response: undefined Jan 08 10:37:42 music volumio[22761]: } Jan 08 10:37:42 music volumio[22761]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:37:43 music sudo[23104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 10:36' Jan 08 10:37:43 music sudo[23104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:43 music sudo[23104]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:43 music volumio-remote-updater[696]: [2026-01-08 10:37:43] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 08 10:37:43 music volumio-remote-updater[696]: [2026-01-08 10:37:43] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 08 10:37:43 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:43 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 08 10:37:43 music systemd[1]: volumio.service: Consumed 26.461s CPU time. Jan 08 10:37:43 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:37:43 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:37:43 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 182. Jan 08 10:37:43 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:37:43 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 08 10:37:43 music systemd[1]: volumio.service: Consumed 26.461s CPU time. Jan 08 10:37:43 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 08 10:37:43 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:37:44 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 08 10:37:44 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:44 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:44 music go-librespot[23131]: go-librespot daemon starting... Jan 08 10:37:44 music go-librespot[23132]: time="2026-01-08T10:37:44-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:44 music go-librespot[23132]: time="2026-01-08T10:37:44-05:00" level=debug msg="app state loaded" Jan 08 10:37:44 music go-librespot[23132]: time="2026-01-08T10:37:44-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-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 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-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 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-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 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=info msg="zeroconf server listening on port 32823" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=debug msg="obtained new client token: AADK5ptNZy+zo1EjGdD+iKyGlBILVNRMKKzbYAg25wSwuhLE0Xhyd97tmzkZZL3qz3O4mZ4dYfSuWm2H6gG/T0gPz5I/FmHEAFBJKc+7suRwYwulb4w++hWHqezNd84VaW9sU9ESdcmqz14lRYaEJpUvBx9pJ+tPOxYURO1akDBUd7/q0+o15sOQnkqa9m3+n4Dl3Ignx5tyPJkdp2/9CIet/eJT+dg5+20vIX/9B2+HU7E6EIXTShw=" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=debug msg="completed challenge" Jan 08 10:37:45 music go-librespot[23132]: time="2026-01-08T10:37:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:45 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:45 music volumio[23116]: info: ----- Volumio3 ---- Jan 08 10:37:45 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:45 music volumio[23116]: info: ----- System startup ---- Jan 08 10:37:45 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:46 music go-librespot[23132]: time="2026-01-08T10:37:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:46 music go-librespot[23132]: time="2026-01-08T10:37:46-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:46 music go-librespot[23132]: time="2026-01-08T10:37:46-05:00" level=debug msg="completed challenge" Jan 08 10:37:46 music go-librespot[23132]: time="2026-01-08T10:37:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:46 music volumio[23116]: info: MYVOLUMIO Environment detected Jan 08 10:37:46 music volumio[23116]: info: Plugin folders cleanup Jan 08 10:37:46 music volumio[23116]: info: Scanning into folder /volumio/app/plugins/ Jan 08 10:37:46 music volumio[23116]: info: Scanning category audio_interface Jan 08 10:37:46 music volumio[23116]: info: Scanning category miscellanea Jan 08 10:37:46 music volumio[23116]: info: Scanning category music_service Jan 08 10:37:46 music volumio[23116]: info: Scanning category plugins.json Jan 08 10:37:46 music volumio[23116]: info: Scanning category system_controller Jan 08 10:37:46 music volumio[23116]: info: Scanning category user_interface Jan 08 10:37:46 music volumio[23116]: info: Scanning into folder /data/plugins/ Jan 08 10:37:46 music volumio[23116]: info: Scanning category music_service Jan 08 10:37:46 music volumio[23116]: info: Plugin folders cleanup completed Jan 08 10:37:46 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:46 music volumio[23116]: info: ----- Core plugins startup ---- Jan 08 10:37:46 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:46 music volumio[23116]: info: Loading plugins from folder /volumio/app/plugins/ Jan 08 10:37:46 music volumio[23116]: info: Adding plugin upnp to MyMusic Plugins Jan 08 10:37:46 music volumio[23116]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 08 10:37:46 music volumio[23116]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 08 10:37:46 music volumio[23116]: info: Loading plugins from folder /data/plugins/ Jan 08 10:37:46 music volumio[23116]: info: Loading plugin "system"... Jan 08 10:37:46 music volumio[23116]: info: Loading plugin "appearance"... Jan 08 10:37:46 music go-librespot[23132]: time="2026-01-08T10:37:46-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 08 10:37:47 music go-librespot[23132]: time="2026-01-08T10:37:47-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 08 10:37:47 music go-librespot[23132]: time="2026-01-08T10:37:47-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:47 music go-librespot[23132]: time="2026-01-08T10:37:47-05:00" level=debug msg="completed challenge" Jan 08 10:37:47 music go-librespot[23132]: time="2026-01-08T10:37:47-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:47 music volumio[23116]: info: Loading plugin "network"... Jan 08 10:37:47 music volumio[23116]: info: Refreshing Cached IP Addresses Jan 08 10:37:47 music sudo[23155]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:37:47 music sudo[23155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:47 music sudo[23157]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:37:47 music sudo[23157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:47 music sudo[23155]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:47 music sudo[23157]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "services"... Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "alsa_controller"... Jan 08 10:37:48 music sudo[23166]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 08 10:37:48 music sudo[23166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:48 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "wizard"... Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "networkfs"... Jan 08 10:37:48 music go-librespot[23132]: time="2026-01-08T10:37:48-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:37:48 music volumio[23116]: info: Starting Udev Watcher for removable devices Jan 08 10:37:48 music volumio[23116]: info: Ignoring mount for partition: boot Jan 08 10:37:48 music volumio[23116]: info: Ignoring mount for partition: volumio Jan 08 10:37:48 music volumio[23116]: info: Ignoring mount for partition: volumio_data Jan 08 10:37:48 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "volumio_command_line_client"... Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "upnp"... Jan 08 10:37:48 music volumio[23116]: info: [1767886668175] Starting Upmpd Daemon Jan 08 10:37:48 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "my_music"... Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "mpd"... Jan 08 10:37:48 music go-librespot[23132]: time="2026-01-08T10:37:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:49758->104.199.65.9:443: read: connection reset by peer" Jan 08 10:37:48 music volumio[23116]: info: Loading plugin "upnp_browser"... Jan 08 10:37:48 music sudo[23166]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:48 music volumio-remote-updater[696]: [2026-01-08 10:37:48] [connect] Successful connection Jan 08 10:37:48 music go-librespot[23132]: time="2026-01-08T10:37:48-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=debug msg="completed challenge" Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:49 music go-librespot[23132]: time="2026-01-08T10:37:49-05:00" level=debug msg="completed challenge" Jan 08 10:37:50 music go-librespot[23132]: time="2026-01-08T10:37:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:50 music go-librespot[23132]: time="2026-01-08T10:37:50-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 08 10:37:50 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:37:50 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:37:50 music volumio[23116]: info: Starting UPNP Browser Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "alarm-clock"... Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "airplay_emulation"... Jan 08 10:37:50 music volumio[23116]: info: Starting Shairport Sync Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "last_100"... Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "webradio"... Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "i2s_dacs"... Jan 08 10:37:50 music volumio[23116]: info: I2S DAC not set, start Auto-detection Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "volumiodiscovery"... Jan 08 10:37:50 music volumio[23116]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:50 music volumio[23116]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:50 music volumio[23116]: *** WARNING *** For more information see Jan 08 10:37:50 music volumio[23116]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:50 music volumio[23116]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:50 music volumio[23116]: *** WARNING *** For more information see Jan 08 10:37:50 music node[23116]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:50 music node[23116]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:50 music node[23116]: *** WARNING *** For more information see Jan 08 10:37:50 music node[23116]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:37:50 music node[23116]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:37:50 music node[23116]: *** WARNING *** For more information see Jan 08 10:37:50 music volumio[23116]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 08 10:37:50 music volumio[23116]: info: Discovery: Started advertising with name: music Jan 08 10:37:50 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:37:50 music volumio[23116]: info: Loading plugin "spop"... Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "outputs"... Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "albumart"... Jan 08 10:37:51 music volumio[23116]: info: Plugin example_plugin is not enabled Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "inputs"... Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "updater_comm"... Jan 08 10:37:51 music volumio[23116]: info: Plugin mpdemulation is not enabled Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "rest_api"... Jan 08 10:37:51 music volumio[23116]: info: Loading plugin "websocket"... Jan 08 10:37:51 music volumio[23116]: info: Starting Socket.io Server version 1.7.4 Jan 08 10:37:51 music volumio[23116]: info: Loading i18n strings for locale en Jan 08 10:37:51 music volumio[23116]: Updating browse sources language Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::initPlayerControls Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:51 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:52 music volumio[23116]: Express server listening on port 3000 Jan 08 10:37:52 music volumio[23116]: [Metrics] WebUI: 6s 612.01ms Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::resetVolumioState Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::getcurrentVolume Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: Volumio Network Manager: Network status updated: 1 Jan 08 10:37:52 music volumio-remote-updater[696]: [2026-01-08 10:37:52] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767886668 101 Jan 08 10:37:52 music volumio[23190]: Forking 3 albumart workers Jan 08 10:37:52 music volumio[23116]: 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 08 10:37:52 music volumio[23116]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::pushState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::updateTrackBlock Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrackBlock Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:37:52 music volumio[23116]: info: Reloading queue from file Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::setRepeat null single undefined Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::pushState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::setRandom null Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::pushState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:52 music volumio[23116]: info: Setting Device type: Raspberry PI Jan 08 10:37:52 music volumio[23116]: info: Listing playlists Jan 08 10:37:52 music volumio[23116]: info: Listing playlists Jan 08 10:37:52 music volumio[23116]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:37:52 music volumio[23116]: info: CoreStateMachine::pushState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioPushState Jan 08 10:37:52 music volumio[23116]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:52 music volumio[23116]: info: Discovery: Found device music Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:37:52 music volumio[23116]: info: Discovery: Found device music Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:52 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:52 music volumio[23116]: info: Completed loading Core Plugins Jan 08 10:37:52 music volumio[23116]: info: Preparing to generate the ALSA configuration file Jan 08 10:37:52 music volumio[23116]: info: Asound.conf file unchanged, so no further update is needed Jan 08 10:37:52 music volumio[23116]: info: Output device has changed, restarting MPD Jan 08 10:37:52 music volumio[23116]: info: Output device has changed, restarting Shairport Sync Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:52 music sudo[23248]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:52 music sudo[23248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:52 music sudo[23246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:52 music volumio[23116]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:52 music volumio[23116]: info: ___________ START PLUGINS ___________ Jan 08 10:37:52 music sudo[23246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:52 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 10:37:52 music sudo[23246]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:52 music volumio[23116]: info: ControllerMpd::onStart: Initializing MPD Jan 08 10:37:52 music volumio[23116]: info: Creating MPD Configuration file Jan 08 10:37:52 music sudo[23256]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:52 music volumio[23116]: info: [1767886672864] CoreMusicLibrary::Adding element Media Servers Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:52 music sudo[23256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:52 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:52 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:52 music systemd[1]: mpd.service: Consumed 4.227s CPU time. Jan 08 10:37:52 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:52 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:52 music sudo[23256]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:52 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:52 music volumio[23116]: info: UPNP Browser: Client initialized successfully Jan 08 10:37:52 music sudo[23258]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:37:52 music sudo[23258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:52 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:52 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:52 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:53 music volumio[23116]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:53 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 08 10:37:53 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:53 music volumio[23116]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:53 music volumio[23116]: info: [1767886673087] CoreMusicLibrary::Adding element Last_100 Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:53 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:53 music go-librespot[23271]: go-librespot daemon starting... Jan 08 10:37:53 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:37:53 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:37:53 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:37:53 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:37:53 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:37:53 music volumio[23116]: info: [1767886673123] CoreMusicLibrary::Adding element Webradio Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:37:53 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:37:53 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=debug msg="app state loaded" Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:53 music volumio[23116]: info: Initializing BBC Radios Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:53 music volumio[23116]: info: Creating Spotify config file Jan 08 10:37:53 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:53 music sudo[23279]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 10:37:53 music sudo[23279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 10:37:53 music sudo[23279]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-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 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-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 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-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 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=info msg="zeroconf server listening on port 33083" Jan 08 10:37:53 music volumio[23116]: info: Volumio Calling Home Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=debug msg="obtained new client token: AAD8YLa4S2Q0xYzzuW6XNMvvsbJ6dm93RDRw3ol7qU07DPbMkOcq97uL0hw84UQ2p40eRjMzbGZK16myYnMy3qqnj+tgJlwlG72Gwola6Hpy2cVYrt9NFDG8qlZJJsot+haFdbb65qHBYQdZY6kn5MAvi3WHks4pyA/t+DvoJAdu6FmP8JqeF6Y7KxGBy0ioQZa78sUNWv5NQ2Bvv8wH2LD26hU7/zCKjzlGQdeqA4I+pdBRwbw87mI=" Jan 08 10:37:53 music go-librespot[23272]: time="2026-01-08T10:37:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:54 music go-librespot[23272]: time="2026-01-08T10:37:54-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:54 music go-librespot[23272]: time="2026-01-08T10:37:54-05:00" level=debug msg="completed challenge" Jan 08 10:37:54 music go-librespot[23272]: time="2026-01-08T10:37:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:54 music volumio[23205]: Starting albumart workers Jan 08 10:37:54 music volumio[23116]: info: MPD Permissions set Jan 08 10:37:54 music volumio[23116]: info: MPD Permissions set Jan 08 10:37:54 music volumio[23116]: info: Volumio called home Jan 08 10:37:54 music volumio[23116]: info: Spotify config file written Jan 08 10:37:54 music volumio[23116]: 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 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23206]: Starting albumart workers Jan 08 10:37:54 music sudo[23304]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 10:37:54 music sudo[23304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:37:54 music volumio[23116]: info: No need to fix Spotify hosts Jan 08 10:37:54 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 08 10:37:54 music volumio[23207]: Starting albumart workers Jan 08 10:37:54 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 08 10:37:54 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:54 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:37:54 music go-librespot[23316]: go-librespot daemon starting... Jan 08 10:37:54 music sudo[23304]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:54 music go-librespot[23317]: time="2026-01-08T10:37:54-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:37:54 music go-librespot[23317]: time="2026-01-08T10:37:54-05:00" level=debug msg="app state loaded" Jan 08 10:37:54 music go-librespot[23317]: time="2026-01-08T10:37:54-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:37:55 music volumio[23116]: info: Starting Shairport Sync Jan 08 10:37:55 music volumio[23116]: info: Starting Shairport Sync Jan 08 10:37:55 music volumio[23116]: info: Starting Shairport Sync Jan 08 10:37:55 music sudo[23328]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:55 music sudo[23328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:55 music volumio[23116]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 08 10:37:55 music sudo[23329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:55 music sudo[23329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:55 music sudo[23331]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:37:55 music sudo[23331]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-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 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-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 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-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 08 10:37:55 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:55 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=info msg="zeroconf server listening on port 44867" Jan 08 10:37:55 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:55 music systemd[1]: shairport-sync.service: Consumed 1.849s CPU time. Jan 08 10:37:55 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:55 music sudo[23328]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:55 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:37:55 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:37:55 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=debug msg="obtained new client token: AAAoGmy8bA2OMgUfpYS1+qq8k39kprMwl1GB5CrTWjti4zoOviH4K1aIOxzwEaWnIY0CM5C/ZcmDhHwT6Mglj/XqC4GKTjL+qS905ef2biQiodWl2iOPpPPr3BJ5qbHKZC12tFWrBJQfbLVtybuT86os+ssuK2V2G41rzdTnZqUfuD4ritwn8XT9iw4j4wKUPSeSQmnJraLlKNZcs1MMVjMfZ1/5w4zbYY2MM8Q78DrYDYQNqjsJkbI=" Jan 08 10:37:55 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:37:55 music sudo[23331]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:55 music sudo[23329]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=debug msg="completed challenge" Jan 08 10:37:55 music go-librespot[23317]: time="2026-01-08T10:37:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:55 music volumio[23116]: info: Shairport-Sync Started Jan 08 10:37:55 music volumio[23116]: Error adding Membership: Error: addMembership EINVAL Jan 08 10:37:55 music volumio[23116]: info: Shairport-Sync Started Jan 08 10:37:55 music volumio[23116]: info: Shairport-Sync Started Jan 08 10:37:55 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:55 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:56 music go-librespot[23317]: time="2026-01-08T10:37:56-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:37:56 music go-librespot[23317]: time="2026-01-08T10:37:56-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:56 music go-librespot[23317]: time="2026-01-08T10:37:56-05:00" level=debug msg="completed challenge" Jan 08 10:37:56 music go-librespot[23317]: time="2026-01-08T10:37:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:57 music go-librespot[23317]: time="2026-01-08T10:37:57-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:37:57 music go-librespot[23317]: time="2026-01-08T10:37:57-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:57 music go-librespot[23317]: time="2026-01-08T10:37:57-05:00" level=debug msg="completed challenge" Jan 08 10:37:57 music go-librespot[23317]: time="2026-01-08T10:37:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:57 music mpd[23297]: 2026-01-08T10:37:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 10:37:57 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 10:37:57 music sudo[23248]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:57 music sudo[23258]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:57 music volumio[23116]: info: Completed starting Core Plugins Jan 08 10:37:57 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:57 music volumio[23116]: info: ----- MyVolumio plugins startup ---- Jan 08 10:37:57 music volumio[23116]: info: ------------------------------------------- Jan 08 10:37:57 music volumio[23116]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 10:37:57 music volumio[23116]: error: MPD error: The expression evaluated to a falsy value: Jan 08 10:37:57 music volumio[23116]: assert.ok(self.idling) Jan 08 10:37:57 music volumio[23116]: error: The expression evaluated to a falsy value: Jan 08 10:37:57 music volumio[23116]: assert.ok(self.idling) Jan 08 10:37:57 music volumio[23116]: error: updateQueue error: null Jan 08 10:37:57 music volumio[23116]: info: MPD running with PID23297 Jan 08 10:37:57 music volumio[23116]: ,establishing connection Jan 08 10:37:57 music volumio[23116]: error: updateQueue error: null Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="completed challenge" Jan 08 10:37:58 music volumio[23116]: info: go-librespot daemon successfully initialized Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:58 music sudo[23392]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:37:58 music sudo[23392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:58 music sudo[23394]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:37:58 music sudo[23394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:58 music sudo[23392]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:58 music sudo[23394]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:58 music sudo[23397]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 10:37:58 music sudo[23397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:37:58 music sudo[23397]: pam_unix(sudo:session): session closed for user root Jan 08 10:37:58 music volumio[23116]: info: Upmpdcli Daemon Started Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:58 music go-librespot[23317]: time="2026-01-08T10:37:58-05:00" level=debug msg="completed challenge" Jan 08 10:37:59 music go-librespot[23317]: time="2026-01-08T10:37:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:37:59 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:37:59 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:37:59 music go-librespot[23317]: time="2026-01-08T10:37:59-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:37:59 music go-librespot[23317]: time="2026-01-08T10:37:59-05:00" level=debug msg="completed keyexchange" Jan 08 10:37:59 music go-librespot[23317]: time="2026-01-08T10:37:59-05:00" level=debug msg="completed challenge" Jan 08 10:38:00 music go-librespot[23317]: time="2026-01-08T10:38:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:00 music go-librespot[23317]: time="2026-01-08T10:38:00-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 08 10:38:00 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:00 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:38:00 music sudo[23403]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:38:00 music sudo[23403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:00 music sudo[23405]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:38:00 music sudo[23405]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:00 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 10:38:00 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 10:38:00 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 10:38:00 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 10:38:00 music sudo[23405]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:00 music sudo[23403]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:00 music mpd_monitor.sh[23410]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 10:38:00 music volumio[23116]: info: Successfully started MPD Monitor Jan 08 10:38:00 music volumio[23116]: info: Successfully started MPD Monitor Jan 08 10:38:01 music volumio[23116]: info: Initializing connection to go-librespot Websocket Jan 08 10:38:01 music volumio[23116]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:38:02 music volumio[23116]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 08 10:38:03 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 08 10:38:03 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:03 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:03 music go-librespot[23414]: go-librespot daemon starting... Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=debug msg="app state loaded" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-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 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-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 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-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 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=info msg="zeroconf server listening on port 35445" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=debug msg="obtained new client token: AAD/2b/hp9/Vg76rDxzf7nrZIGQPolWzwj/UuFJaI0JyZtK1vh+daCkOZ6U2BFlCtXNRPxElgBkQ+k1lGkv6wiTfibcKHDrABlMLSqoE7FIQo+d9BARtmfTXNjBX2yU3h31nbDEUpEP64uuF7T+XRBVRCXxKJk6+CF/giS/E1KIU+Br5Ooxk5gJsZgemGwbT9KD0oDNUb21oQqiblcrAeXRDUine4/cmKOSNB0STLlpLdAK9yQJqJOQ=" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:03 music go-librespot[23415]: time="2026-01-08T10:38:03-05:00" level=debug msg="completed challenge" Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:04 music volumio[23116]: info: Initializing connection to go-librespot Websocket Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=debug msg="new websocket client" Jan 08 10:38:04 music volumio[23116]: info: Connection to go-librespot Websocket established Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=debug msg="completed challenge" Jan 08 10:38:04 music go-librespot[23415]: time="2026-01-08T10:38:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:05 music go-librespot[23415]: time="2026-01-08T10:38:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:05 music go-librespot[23415]: time="2026-01-08T10:38:05-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:05 music go-librespot[23415]: time="2026-01-08T10:38:05-05:00" level=debug msg="completed challenge" Jan 08 10:38:05 music go-librespot[23415]: time="2026-01-08T10:38:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 08 10:38:05 music volumio[23116]: info: Adding plugin bluetooth to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin multiroom to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin metavolumio to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin cd_controller to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 08 10:38:05 music volumio[23116]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 08 10:38:06 music go-librespot[23415]: time="2026-01-08T10:38:06-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 08 10:38:06 music go-librespot[23415]: time="2026-01-08T10:38:06-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:06 music go-librespot[23415]: time="2026-01-08T10:38:06-05:00" level=debug msg="completed challenge" Jan 08 10:38:06 music go-librespot[23415]: time="2026-01-08T10:38:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:06 music volumio[23116]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 08 10:38:06 music volumio[23116]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 08 10:38:06 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:06 music volumio[23116]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:06 music volumio[23116]: info: Starting MyVolumio Remote Streaming Endpoints Jan 08 10:38:06 music volumio[23116]: info: MyVolumio login type: Token Jan 08 10:38:06 music volumio[23116]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 08 10:38:06 music volumio[23116]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 08 10:38:07 music go-librespot[23415]: time="2026-01-08T10:38:07-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:38:07 music go-librespot[23415]: time="2026-01-08T10:38:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.3.63:33820->104.199.65.9:443: read: connection reset by peer" Jan 08 10:38:07 music volumio[23116]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 08 10:38:07 music volumio[23116]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 08 10:38:07 music volumio[23116]: info: Streaming services startup Jan 08 10:38:07 music volumio[23116]: info: Starting Streaming Daemon Jan 08 10:38:07 music sudo[23425]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 08 10:38:07 music sudo[23425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:07 music volumio[23116]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 08 10:38:07 music sudo[23425]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:07 music go-librespot[23415]: time="2026-01-08T10:38:07-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:38:08 music volumio[23116]: info: Getting Spotify volume Jan 08 10:38:08 music volumio[23116]: error: Cannot start Volumio Streaming Daemon Jan 08 10:38:08 music volumio[23116]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 08 10:38:08 music volumio[23116]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 08 10:38:08 music volumio[23116]: 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 08 10:38:08 music go-librespot[23415]: time="2026-01-08T10:38:08-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:08 music go-librespot[23415]: time="2026-01-08T10:38:08-05:00" level=debug msg="completed challenge" Jan 08 10:38:08 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:08 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:08 music volumio[23116]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 08 10:38:08 music volumio[23116]: SPOTIFY: SPOTIFY VOLUME undefined Jan 08 10:38:08 music volumio[23116]: SPOTIFY: VOLUMIO VOLUME 86 Jan 08 10:38:08 music volumio[23116]: info: Aligning Spotify Volume to Volumio Volume Jan 08 10:38:08 music volumio[23116]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:08 music volumio[23116]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:08 music volumio[23116]: info: Setting Spotify Volume from Volumio: 86 Jan 08 10:38:08 music go-librespot[23415]: time="2026-01-08T10:38:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:08 music go-librespot[23415]: time="2026-01-08T10:38:08-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 08 10:38:08 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:08 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:38:08 music volumio[23116]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:38:08 music volumio[23116]: Error: socket hang up Jan 08 10:38:08 music volumio[23116]: at connResetException (node:internal/errors:720:14) Jan 08 10:38:08 music volumio[23116]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 08 10:38:08 music volumio[23116]: at Socket.emit (node:events:526:35) Jan 08 10:38:08 music volumio[23116]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 08 10:38:08 music volumio[23116]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 08 10:38:08 music volumio[23116]: code: 'ECONNRESET', Jan 08 10:38:08 music volumio[23116]: response: undefined Jan 08 10:38:08 music volumio[23116]: } Jan 08 10:38:08 music volumio[23116]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:38:09 music sudo[23460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 10:37' Jan 08 10:38:09 music sudo[23460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:09 music sudo[23460]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:11 music volumio-remote-updater[696]: [2026-01-08 10:38:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 08 10:38:11 music volumio-remote-updater[696]: [2026-01-08 10:38:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 08 10:38:11 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:11 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 08 10:38:11 music systemd[1]: volumio.service: Consumed 26.928s CPU time. Jan 08 10:38:11 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:38:11 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 08 10:38:11 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:11 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:11 music go-librespot[23472]: go-librespot daemon starting... Jan 08 10:38:11 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=debug msg="app state loaded" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:38:11 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 183. Jan 08 10:38:11 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 08 10:38:11 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 08 10:38:11 music systemd[1]: volumio.service: Consumed 26.928s CPU time. Jan 08 10:38:11 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-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 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-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 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-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 08 10:38:11 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=info msg="zeroconf server listening on port 45359" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=debug msg="obtained new client token: AABZKWKbCEfk1TKj2ajhJQ4BJD2nuApsQq71tmbk24jLXN9jUsvxbAtdhd2Km1WhXvCQfbXZpjBPkKmjjHN5FjeBwsM6XqN188GA1AiFmaGK2FNoQwjW5K6UQp2MljVfEcMG9PBKWpnhIW7M5EszOLVpCuh8gXmJz5e/mGQ4mSkxXa3ye5ylyJJgRm3KAaQA8JIuwir8sAqQpOAtTMx9AmESn/JvW/XEqF2Swd/d20vlp/BWmTlZfiQ=" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=debug msg="completed challenge" Jan 08 10:38:11 music go-librespot[23475]: time="2026-01-08T10:38:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:12 music go-librespot[23475]: time="2026-01-08T10:38:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:38:12 music go-librespot[23475]: time="2026-01-08T10:38:12-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:12 music go-librespot[23475]: time="2026-01-08T10:38:12-05:00" level=debug msg="completed challenge" Jan 08 10:38:12 music go-librespot[23475]: time="2026-01-08T10:38:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:13 music go-librespot[23475]: time="2026-01-08T10:38:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:13 music go-librespot[23475]: time="2026-01-08T10:38:13-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:13 music go-librespot[23475]: time="2026-01-08T10:38:13-05:00" level=debug msg="completed challenge" Jan 08 10:38:13 music go-librespot[23475]: time="2026-01-08T10:38:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:13 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:13 music volumio[23485]: info: ----- Volumio3 ---- Jan 08 10:38:13 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:13 music volumio[23485]: info: ----- System startup ---- Jan 08 10:38:13 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:14 music go-librespot[23475]: time="2026-01-08T10:38:14-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 08 10:38:14 music go-librespot[23475]: time="2026-01-08T10:38:14-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:14 music go-librespot[23475]: time="2026-01-08T10:38:14-05:00" level=debug msg="completed challenge" Jan 08 10:38:14 music volumio[23485]: info: MYVOLUMIO Environment detected Jan 08 10:38:14 music volumio[23485]: info: Plugin folders cleanup Jan 08 10:38:14 music volumio[23485]: info: Scanning into folder /volumio/app/plugins/ Jan 08 10:38:14 music volumio[23485]: info: Scanning category audio_interface Jan 08 10:38:14 music volumio[23485]: info: Scanning category miscellanea Jan 08 10:38:14 music volumio[23485]: info: Scanning category music_service Jan 08 10:38:14 music volumio[23485]: info: Scanning category plugins.json Jan 08 10:38:14 music volumio[23485]: info: Scanning category system_controller Jan 08 10:38:14 music volumio[23485]: info: Scanning category user_interface Jan 08 10:38:14 music volumio[23485]: info: Scanning into folder /data/plugins/ Jan 08 10:38:14 music volumio[23485]: info: Scanning category music_service Jan 08 10:38:14 music volumio[23485]: info: Plugin folders cleanup completed Jan 08 10:38:14 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:14 music volumio[23485]: info: ----- Core plugins startup ---- Jan 08 10:38:14 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:14 music volumio[23485]: info: Loading plugins from folder /volumio/app/plugins/ Jan 08 10:38:14 music volumio[23485]: info: Adding plugin upnp to MyMusic Plugins Jan 08 10:38:14 music volumio[23485]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 08 10:38:14 music volumio[23485]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 08 10:38:14 music volumio[23485]: info: Loading plugins from folder /data/plugins/ Jan 08 10:38:14 music volumio[23485]: info: Loading plugin "system"... Jan 08 10:38:14 music go-librespot[23475]: time="2026-01-08T10:38:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:14 music volumio[23485]: info: Loading plugin "appearance"... Jan 08 10:38:15 music go-librespot[23475]: time="2026-01-08T10:38:15-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:38:15 music go-librespot[23475]: time="2026-01-08T10:38:15-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:15 music go-librespot[23475]: time="2026-01-08T10:38:15-05:00" level=debug msg="completed challenge" Jan 08 10:38:15 music go-librespot[23475]: time="2026-01-08T10:38:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "network"... Jan 08 10:38:15 music volumio[23485]: info: Refreshing Cached IP Addresses Jan 08 10:38:15 music sudo[23513]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:38:15 music sudo[23513]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:15 music sudo[23515]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:38:15 music sudo[23515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:15 music sudo[23513]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "services"... Jan 08 10:38:15 music sudo[23515]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "alsa_controller"... Jan 08 10:38:15 music sudo[23523]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 08 10:38:15 music sudo[23523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:15 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "wizard"... Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "networkfs"... Jan 08 10:38:15 music volumio[23485]: info: Starting Udev Watcher for removable devices Jan 08 10:38:15 music volumio[23485]: info: Ignoring mount for partition: boot Jan 08 10:38:15 music volumio[23485]: info: Ignoring mount for partition: volumio Jan 08 10:38:15 music volumio[23485]: info: Ignoring mount for partition: volumio_data Jan 08 10:38:15 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "volumio_command_line_client"... Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "upnp"... Jan 08 10:38:15 music volumio[23485]: info: [1767886695859] Starting Upmpd Daemon Jan 08 10:38:15 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "my_music"... Jan 08 10:38:15 music volumio[23485]: info: Loading plugin "mpd"... Jan 08 10:38:16 music go-librespot[23475]: time="2026-01-08T10:38:16-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:38:16 music go-librespot[23475]: time="2026-01-08T10:38:16-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:16 music go-librespot[23475]: time="2026-01-08T10:38:16-05:00" level=debug msg="completed challenge" Jan 08 10:38:16 music volumio-remote-updater[696]: [2026-01-08 10:38:16] [connect] Successful connection Jan 08 10:38:16 music volumio[23485]: info: Loading plugin "upnp_browser"... Jan 08 10:38:16 music go-librespot[23475]: time="2026-01-08T10:38:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:16 music go-librespot[23475]: time="2026-01-08T10:38:16-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 08 10:38:16 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:16 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:38:16 music sudo[23523]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:17 music volumio[23485]: info: Starting UPNP Browser Jan 08 10:38:17 music volumio[23485]: info: Loading plugin "alarm-clock"... Jan 08 10:38:17 music volumio[23485]: info: Loading plugin "airplay_emulation"... Jan 08 10:38:17 music volumio[23485]: info: Starting Shairport Sync Jan 08 10:38:17 music volumio[23485]: info: Loading plugin "last_100"... Jan 08 10:38:18 music volumio[23485]: info: Loading plugin "webradio"... Jan 08 10:38:18 music volumio[23485]: info: Loading plugin "i2s_dacs"... Jan 08 10:38:18 music volumio[23485]: info: I2S DAC not set, start Auto-detection Jan 08 10:38:18 music volumio[23485]: info: Loading plugin "volumiodiscovery"... Jan 08 10:38:18 music volumio[23485]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:38:18 music volumio[23485]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:38:18 music volumio[23485]: *** WARNING *** For more information see Jan 08 10:38:18 music volumio[23485]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:38:18 music volumio[23485]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:38:18 music volumio[23485]: *** WARNING *** For more information see Jan 08 10:38:18 music node[23485]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 08 10:38:18 music node[23485]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:38:18 music node[23485]: *** WARNING *** For more information see Jan 08 10:38:18 music node[23485]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 08 10:38:18 music node[23485]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 08 10:38:18 music node[23485]: *** WARNING *** For more information see Jan 08 10:38:18 music volumio[23485]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 08 10:38:18 music volumio[23485]: info: Discovery: Started advertising with name: music Jan 08 10:38:18 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 08 10:38:18 music volumio[23485]: info: Loading plugin "spop"... Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "outputs"... Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "albumart"... Jan 08 10:38:19 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 08 10:38:19 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:19 music volumio[23485]: info: Plugin example_plugin is not enabled Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "inputs"... Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "updater_comm"... Jan 08 10:38:19 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:19 music go-librespot[23548]: go-librespot daemon starting... Jan 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-05:00" level=debug msg="app state loaded" Jan 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:38:19 music volumio[23485]: info: Plugin mpdemulation is not enabled Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "rest_api"... Jan 08 10:38:19 music volumio[23485]: info: Loading plugin "websocket"... Jan 08 10:38:19 music volumio[23485]: info: Starting Socket.io Server version 1.7.4 Jan 08 10:38:19 music volumio[23485]: info: Loading i18n strings for locale en Jan 08 10:38:19 music volumio[23485]: Updating browse sources language Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::initPlayerControls Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:38:19 music volumio[23485]: Express server listening on port 3000 Jan 08 10:38:19 music volumio[23485]: [Metrics] WebUI: 6s 652.51ms Jan 08 10:38:19 music volumio[23485]: info: CoreStateMachine::resetVolumioState Jan 08 10:38:19 music volumio[23485]: info: CoreStateMachine::getcurrentVolume Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-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 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-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 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-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 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-05:00" level=info msg="zeroconf server listening on port 33039" Jan 08 10:38:19 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:19 music volumio[23485]: info: Volumio Network Manager: Network status updated: 1 Jan 08 10:38:19 music volumio-remote-updater[696]: [2026-01-08 10:38:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767886696 101 Jan 08 10:38:19 music volumio[23549]: Forking 3 albumart workers Jan 08 10:38:19 music volumio[23485]: 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 08 10:38:19 music go-librespot[23558]: time="2026-01-08T10:38:19-05:00" level=debug msg="obtained new client token: AAAG0mNPOyzHdAGXCaWjRDul3d/fvEQGBEXrF0HvQ2mPgl3ti2tokb3CMOm2EoQHYA8WAtQaUaLBfK8aRxRghO/nGTgH3e/Yb7BH4Mc576PBM+f2LHAIcfLRyGdq96JeSGdCKZux8PXmNgrtCOFqmDuhYnMScKTVKDPEWBRNkHNnTo0x9XwBo10zlkO9+bHkL/UIYloemIfxFadWS7qIDoTA71TNFAmqhvRrlcUIBDO9Cr5GS+3XVos=" Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:38:20 music volumio[23485]: info: Reloading queue from file Jan 08 10:38:20 music volumio[23485]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::pushState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioPushState Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::updateTrackBlock Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrackBlock Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioRetrievevolume Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="completed challenge" Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::setRepeat null single undefined Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::pushState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioPushState Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::setRandom null Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::pushState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioPushState Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:20 music volumio[23485]: info: Setting Device type: Raspberry PI Jan 08 10:38:20 music volumio[23485]: info: Listing playlists Jan 08 10:38:20 music volumio[23485]: info: Listing playlists Jan 08 10:38:20 music volumio[23485]: info: VolumeController:: Volume=86 Mute =false Jan 08 10:38:20 music volumio[23485]: info: CoreStateMachine::pushState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioPushState Jan 08 10:38:20 music volumio[23485]: info: Completed loading Core Plugins Jan 08 10:38:20 music volumio[23485]: info: Preparing to generate the ALSA configuration file Jan 08 10:38:20 music volumio[23485]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:38:20 music volumio[23485]: info: Discovery: Found device music Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 08 10:38:20 music volumio[23485]: info: Discovery: Found device music Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:20 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:20 music volumio[23485]: info: Asound.conf file unchanged, so no further update is needed Jan 08 10:38:20 music volumio[23485]: info: Output device has changed, restarting MPD Jan 08 10:38:20 music volumio[23485]: info: Output device has changed, restarting Shairport Sync Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:20 music sudo[23615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:38:20 music sudo[23615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:20 music sudo[23619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:38:20 music sudo[23619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:20 music sudo[23615]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:20 music volumio[23485]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:38:20 music volumio[23485]: info: ___________ START PLUGINS ___________ Jan 08 10:38:20 music volumio[23485]: info: ControllerMpd::onStart: Initializing MPD Jan 08 10:38:20 music volumio[23485]: info: Creating MPD Configuration file Jan 08 10:38:20 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 08 10:38:20 music sudo[23625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 08 10:38:20 music sudo[23625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:20 music sudo[23627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 08 10:38:20 music sudo[23627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:20 music sudo[23625]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:38:20 music volumio[23485]: info: [1767886700564] CoreMusicLibrary::Adding element Media Servers Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:38:20 music volumio[23485]: info: UPNP Browser: Client initialized successfully Jan 08 10:38:20 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:38:20 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:38:20 music systemd[1]: mpd.service: Consumed 4.151s CPU time. Jan 08 10:38:20 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:38:20 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:38:20 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:20 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:38:20 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:38:20 music systemd[1]: mpd.service: Deactivated successfully. Jan 08 10:38:20 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 08 10:38:20 music systemd[1]: mpd.socket: Deactivated successfully. Jan 08 10:38:20 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 08 10:38:20 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 08 10:38:20 music volumio[23485]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 08 10:38:20 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:38:20 music volumio[23485]: info: [1767886700756] CoreMusicLibrary::Adding element Last_100 Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:38:20 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 08 10:38:20 music volumio[23485]: info: [1767886700770] CoreMusicLibrary::Adding element Webradio Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:38:20 music volumio[23485]: info: Initializing BBC Radios Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=debug msg="completed challenge" Jan 08 10:38:20 music go-librespot[23558]: time="2026-01-08T10:38:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:20 music volumio[23485]: info: Creating Spotify config file Jan 08 10:38:20 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:21 music sudo[23641]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 08 10:38:21 music sudo[23641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 08 10:38:21 music sudo[23641]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:21 music go-librespot[23558]: time="2026-01-08T10:38:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:21 music volumio[23485]: info: Volumio Calling Home Jan 08 10:38:21 music go-librespot[23558]: time="2026-01-08T10:38:21-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:21 music go-librespot[23558]: time="2026-01-08T10:38:21-05:00" level=debug msg="completed challenge" Jan 08 10:38:21 music go-librespot[23558]: time="2026-01-08T10:38:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:21 music volumio[23574]: Starting albumart workers Jan 08 10:38:21 music volumio[23576]: Starting albumart workers Jan 08 10:38:22 music volumio[23573]: Starting albumart workers Jan 08 10:38:22 music volumio[23485]: info: MPD Permissions set Jan 08 10:38:22 music volumio[23485]: info: MPD Permissions set Jan 08 10:38:22 music volumio[23485]: info: Volumio called home Jan 08 10:38:22 music volumio[23485]: info: Spotify config file written Jan 08 10:38:22 music volumio[23485]: 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 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music sudo[23663]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 08 10:38:22 music sudo[23663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 08 10:38:22 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 08 10:38:22 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:22 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:22 music go-librespot[23672]: go-librespot daemon starting... Jan 08 10:38:22 music sudo[23663]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:22 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-05:00" level=debug msg="app state loaded" Jan 08 10:38:22 music volumio[23485]: info: No need to fix Spotify hosts Jan 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-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 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-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 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-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 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-05:00" level=info msg="zeroconf server listening on port 35201" Jan 08 10:38:22 music go-librespot[23676]: time="2026-01-08T10:38:22-05:00" level=debug msg="obtained new client token: AACaKrrCCKs9UAidycG68jJI4y0gJqXyI4AV2a7AaI2bHbi83m9GvIvnnII/Pxq65KfAhF3nqgSkSLxf4owD0Zb5iFLgBszz78RmflBpd4H/LQPCgxdYMHiasQlniFG+HbT2o5D9M0R9o/ytKpajhbyUNJOhxe2GiGljDSaTgibpJK9DhHsPA9mxovxNpFV5zD4t9BkLxW+iLbx1PVCr5sAwSDrEcLcWSq0udvpvV60I1y52o0g7NzU=" Jan 08 10:38:23 music volumio[23485]: info: Starting Shairport Sync Jan 08 10:38:23 music volumio[23485]: info: Starting Shairport Sync Jan 08 10:38:23 music volumio[23485]: info: Starting Shairport Sync Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:38:23 music sudo[23688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:38:23 music sudo[23688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:23 music sudo[23692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:38:23 music sudo[23692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="completed challenge" Jan 08 10:38:23 music sudo[23690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 08 10:38:23 music sudo[23690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:23 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:23 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:38:23 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:38:23 music systemd[1]: shairport-sync.service: Consumed 1.848s CPU time. Jan 08 10:38:23 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:38:23 music sudo[23688]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:23 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 08 10:38:23 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 08 10:38:23 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:38:23 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 08 10:38:23 music sudo[23692]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:23 music sudo[23690]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:23 music volumio[23485]: info: Shairport-Sync Started Jan 08 10:38:23 music volumio[23485]: Error adding Membership: Error: addMembership EINVAL Jan 08 10:38:23 music volumio[23485]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 08 10:38:23 music volumio[23485]: info: Shairport-Sync Started Jan 08 10:38:23 music volumio[23485]: info: Shairport-Sync Started Jan 08 10:38:23 music volumio[23485]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:23 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=debug msg="completed challenge" Jan 08 10:38:23 music go-librespot[23676]: time="2026-01-08T10:38:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:24 music go-librespot[23676]: time="2026-01-08T10:38:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:24 music go-librespot[23676]: time="2026-01-08T10:38:24-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:24 music go-librespot[23676]: time="2026-01-08T10:38:24-05:00" level=debug msg="completed challenge" Jan 08 10:38:24 music go-librespot[23676]: time="2026-01-08T10:38:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:25 music mpd[23658]: 2026-01-08T10:38:25 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 08 10:38:25 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 08 10:38:25 music sudo[23619]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:25 music sudo[23627]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:25 music volumio[23485]: info: Completed starting Core Plugins Jan 08 10:38:25 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:25 music volumio[23485]: info: ----- MyVolumio plugins startup ---- Jan 08 10:38:25 music volumio[23485]: info: ------------------------------------------- Jan 08 10:38:25 music volumio[23485]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 08 10:38:25 music volumio[23485]: error: MPD error: The expression evaluated to a falsy value: Jan 08 10:38:25 music volumio[23485]: assert.ok(self.idling) Jan 08 10:38:25 music volumio[23485]: error: The expression evaluated to a falsy value: Jan 08 10:38:25 music volumio[23485]: assert.ok(self.idling) Jan 08 10:38:25 music volumio[23485]: error: updateQueue error: null Jan 08 10:38:25 music volumio[23485]: info: MPD running with PID23658 Jan 08 10:38:25 music volumio[23485]: ,establishing connection Jan 08 10:38:25 music volumio[23485]: error: updateQueue error: null Jan 08 10:38:25 music go-librespot[23676]: time="2026-01-08T10:38:25-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 08 10:38:25 music go-librespot[23676]: time="2026-01-08T10:38:25-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:25 music go-librespot[23676]: time="2026-01-08T10:38:25-05:00" level=debug msg="completed challenge" Jan 08 10:38:25 music go-librespot[23676]: time="2026-01-08T10:38:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:25 music sudo[23750]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 08 10:38:25 music sudo[23750]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:25 music sudo[23752]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 08 10:38:25 music sudo[23752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:25 music sudo[23750]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:25 music sudo[23752]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:25 music sudo[23754]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 08 10:38:25 music sudo[23754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:25 music sudo[23754]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:25 music volumio[23485]: info: Upmpdcli Daemon Started Jan 08 10:38:25 music volumio[23485]: info: go-librespot daemon successfully initialized Jan 08 10:38:26 music go-librespot[23676]: time="2026-01-08T10:38:26-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 08 10:38:26 music go-librespot[23676]: time="2026-01-08T10:38:26-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:26 music go-librespot[23676]: time="2026-01-08T10:38:26-05:00" level=debug msg="completed challenge" Jan 08 10:38:26 music go-librespot[23676]: time="2026-01-08T10:38:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:27 music go-librespot[23676]: time="2026-01-08T10:38:27-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:38:27 music go-librespot[23676]: time="2026-01-08T10:38:27-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:27 music go-librespot[23676]: time="2026-01-08T10:38:27-05:00" level=debug msg="completed challenge" Jan 08 10:38:27 music go-librespot[23676]: time="2026-01-08T10:38:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:27 music go-librespot[23676]: time="2026-01-08T10:38:27-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 08 10:38:27 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:27 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:38:28 music sudo[23761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:38:28 music sudo[23761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:28 music sudo[23763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 08 10:38:28 music sudo[23763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:28 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 08 10:38:28 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 08 10:38:28 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 08 10:38:28 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 08 10:38:28 music sudo[23763]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:28 music sudo[23761]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:28 music mpd_monitor.sh[23766]: MPD Monitor Service: Starting MPD Monitor Service Jan 08 10:38:28 music volumio[23485]: info: Successfully started MPD Monitor Jan 08 10:38:28 music volumio[23485]: info: Successfully started MPD Monitor Jan 08 10:38:28 music volumio[23485]: info: Initializing connection to go-librespot Websocket Jan 08 10:38:29 music volumio[23485]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:38:29 music volumio[23485]: info: CoreCommandRouter::volumioGetState Jan 08 10:38:29 music volumio[23485]: info: CorePlayQueue::getTrack 0 Jan 08 10:38:30 music volumio[23485]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 08 10:38:30 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 08 10:38:30 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:30 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 08 10:38:30 music go-librespot[23772]: go-librespot daemon starting... Jan 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-05:00" level=info msg="running go-librespot 0.6.2" Jan 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-05:00" level=debug msg="app state loaded" Jan 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-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 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-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 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-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 08 10:38:30 music go-librespot[23773]: time="2026-01-08T10:38:30-05:00" level=info msg="zeroconf server listening on port 44163" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="obtained new client token: AAB8Wx45UJv/ZgDp7h2FXS773IBCQ/kNW0BmfhxGylz+A/P/7qj9KBo5GFwMHLDj2Zx6DEQfqDD9WW07wq5HBHgZFEkmSXUk6Qh2cIQpyEkv3H9EkyGvIkM7GtsuD655cs/1QRrWROaz2L9l+UtbSp2QPffz5QViEXxmSSuVC4gtWHTlKhNSpDY2Y9xKMyxR0rjOwVCXU7CO+0/h9qy9+M4QtIZE1LwApq/nEPTiEjwt2pVrGe+z" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-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 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="completed challenge" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:31 music go-librespot[23773]: time="2026-01-08T10:38:31-05:00" level=debug msg="completed challenge" Jan 08 10:38:32 music volumio[23485]: info: Initializing connection to go-librespot Websocket Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=debug msg="new websocket client" Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:32 music volumio[23485]: info: Connection to go-librespot Websocket established Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=debug msg="completed challenge" Jan 08 10:38:32 music go-librespot[23773]: time="2026-01-08T10:38:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:33 music go-librespot[23773]: time="2026-01-08T10:38:33-05:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Jan 08 10:38:33 music go-librespot[23773]: time="2026-01-08T10:38:33-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 08 10:38:33 music volumio[23485]: info: Adding plugin bluetooth to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin multiroom to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin metavolumio to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin cd_controller to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 08 10:38:33 music volumio[23485]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 08 10:38:33 music go-librespot[23773]: time="2026-01-08T10:38:33-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:33 music go-librespot[23773]: time="2026-01-08T10:38:33-05:00" level=debug msg="completed challenge" Jan 08 10:38:33 music go-librespot[23773]: time="2026-01-08T10:38:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:34 music go-librespot[23773]: time="2026-01-08T10:38:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 08 10:38:34 music go-librespot[23773]: time="2026-01-08T10:38:34-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:34 music go-librespot[23773]: time="2026-01-08T10:38:34-05:00" level=debug msg="completed challenge" Jan 08 10:38:34 music go-librespot[23773]: time="2026-01-08T10:38:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:34 music volumio[23485]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 08 10:38:34 music volumio[23485]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 08 10:38:34 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:34 music volumio[23485]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 08 10:38:34 music volumio[23485]: info: Starting MyVolumio Remote Streaming Endpoints Jan 08 10:38:34 music volumio[23485]: info: MyVolumio login type: Token Jan 08 10:38:34 music volumio[23485]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 08 10:38:34 music volumio[23485]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 08 10:38:34 music go-librespot[23773]: time="2026-01-08T10:38:34-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 08 10:38:35 music go-librespot[23773]: time="2026-01-08T10:38:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 08 10:38:35 music go-librespot[23773]: time="2026-01-08T10:38:35-05:00" level=debug msg="completed keyexchange" Jan 08 10:38:35 music go-librespot[23773]: time="2026-01-08T10:38:35-05:00" level=debug msg="completed challenge" Jan 08 10:38:35 music go-librespot[23773]: time="2026-01-08T10:38:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 08 10:38:35 music go-librespot[23773]: time="2026-01-08T10:38:35-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 08 10:38:35 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 08 10:38:35 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 08 10:38:35 music volumio[23485]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 08 10:38:35 music volumio[23485]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 08 10:38:35 music volumio[23485]: info: Streaming services startup Jan 08 10:38:35 music volumio[23485]: info: Starting Streaming Daemon Jan 08 10:38:35 music sudo[23783]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 08 10:38:35 music sudo[23783]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 08 10:38:35 music volumio[23485]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 08 10:38:35 music sudo[23783]: pam_unix(sudo:session): session closed for user root Jan 08 10:38:35 music volumio[23485]: info: Getting Spotify volume Jan 08 10:38:35 music volumio[23485]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:38:35 music volumio[23485]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 08 10:38:35 music volumio[23485]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 08 10:38:35 music volumio[23485]: errno: -111, Jan 08 10:38:35 music volumio[23485]: code: 'ECONNREFUSED', Jan 08 10:38:35 music volumio[23485]: syscall: 'connect', Jan 08 10:38:35 music volumio[23485]: address: '127.0.0.1', Jan 08 10:38:35 music volumio[23485]: port: 9879, Jan 08 10:38:35 music volumio[23485]: response: undefined Jan 08 10:38:35 music volumio[23485]: } Jan 08 10:38:35 music volumio[23485]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 08 10:38:36 music sudo[23817]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-08 10:37' Jan 08 10:38:36 music sudo[23817]: 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"