Jan 12 00:11:01 music go-librespot[5713]: time="2026-01-12T00:11:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:01 music go-librespot[5713]: time="2026-01-12T00:11:01-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:01 music go-librespot[5713]: time="2026-01-12T00:11:01-05:00" level=debug msg="completed challenge" Jan 12 00:11:01 music go-librespot[5713]: time="2026-01-12T00:11:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:01 music go-librespot[5713]: time="2026-01-12T00:11:01-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:01 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:01 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:01 music volumio[5413]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Jan 12 00:11:01 music volumio[5413]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:01 music volumio[5413]: Error: socket hang up Jan 12 00:11:01 music volumio[5413]: at connResetException (node:internal/errors:720:14) Jan 12 00:11:01 music volumio[5413]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 12 00:11:01 music volumio[5413]: at Socket.emit (node:events:526:35) Jan 12 00:11:01 music volumio[5413]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 12 00:11:01 music volumio[5413]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 12 00:11:01 music volumio[5413]: code: 'ECONNRESET', Jan 12 00:11:01 music volumio[5413]: response: undefined Jan 12 00:11:01 music volumio[5413]: } Jan 12 00:11:01 music volumio[5413]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:02 music sudo[5784]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 00:10' Jan 12 00:11:02 music sudo[5784]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:02 music sudo[5784]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:03 music volumio-remote-updater[22000]: [2026-01-12 00:11:03] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 12 00:11:03 music volumio-remote-updater[22000]: [2026-01-12 00:11:03] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 12 00:11:03 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:03 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 12 00:11:03 music systemd[1]: volumio.service: Consumed 28.053s CPU time. Jan 12 00:11:03 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:03 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:03 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5854. Jan 12 00:11:03 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:03 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 12 00:11:03 music systemd[1]: volumio.service: Consumed 28.053s CPU time. Jan 12 00:11:03 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 12 00:11:03 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:04 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 12 00:11:04 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:04 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:04 music go-librespot[5818]: go-librespot daemon starting... Jan 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-05:00" level=debug msg="app state loaded" Jan 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-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 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-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 12 00:11:04 music go-librespot[5819]: time="2026-01-12T00:11:04-05:00" level=info msg="zeroconf server listening on port 39435" Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=debug msg="obtained new client token: AAAlwzNlm+CQwsyW4WqF06ypyHj66OoFhnV03m2f4mTw4GrO8LDbDlih8sNPH/vt6A2+nQ6BHn2j2ScmqHC2/EIz1Q3PRcwS3f1uf3pLFoZntFV/hUUbiZE4lEGkF/zShbMM/MJPgHiBxf2EtD4T5vPPg3FNlAToSun2E/rjtEu7XII3ENnziR8T0G2sa78sT66nduHFbxbrMUX61N7u5e2q4dpes/fvKrF4r4tWYOlZxwU9BUaP" Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=debug msg="completed challenge" Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:05 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:05 music volumio[5803]: info: ----- Volumio3 ---- Jan 12 00:11:05 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:05 music volumio[5803]: info: ----- System startup ---- Jan 12 00:11:05 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:05 music go-librespot[5819]: time="2026-01-12T00:11:05-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=debug msg="completed challenge" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:06 music volumio[5803]: info: MYVOLUMIO Environment detected Jan 12 00:11:06 music volumio[5803]: info: Plugin folders cleanup Jan 12 00:11:06 music volumio[5803]: info: Scanning into folder /volumio/app/plugins/ Jan 12 00:11:06 music volumio[5803]: info: Scanning category audio_interface Jan 12 00:11:06 music volumio[5803]: info: Scanning category miscellanea Jan 12 00:11:06 music volumio[5803]: info: Scanning category music_service Jan 12 00:11:06 music volumio[5803]: info: Scanning category plugins.json Jan 12 00:11:06 music volumio[5803]: info: Scanning category system_controller Jan 12 00:11:06 music volumio[5803]: info: Scanning category user_interface Jan 12 00:11:06 music volumio[5803]: info: Scanning into folder /data/plugins/ Jan 12 00:11:06 music volumio[5803]: info: Scanning category music_service Jan 12 00:11:06 music volumio[5803]: info: Plugin folders cleanup completed Jan 12 00:11:06 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:06 music volumio[5803]: info: ----- Core plugins startup ---- Jan 12 00:11:06 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:06 music volumio[5803]: info: Loading plugins from folder /volumio/app/plugins/ Jan 12 00:11:06 music volumio[5803]: info: Adding plugin upnp to MyMusic Plugins Jan 12 00:11:06 music volumio[5803]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 12 00:11:06 music volumio[5803]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 12 00:11:06 music volumio[5803]: info: Loading plugins from folder /data/plugins/ Jan 12 00:11:06 music volumio[5803]: info: Loading plugin "system"... Jan 12 00:11:06 music volumio[5803]: info: Loading plugin "appearance"... Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=debug msg="completed challenge" Jan 12 00:11:06 music go-librespot[5819]: time="2026-01-12T00:11:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "network"... Jan 12 00:11:07 music volumio[5803]: info: Refreshing Cached IP Addresses Jan 12 00:11:07 music sudo[5842]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:11:07 music sudo[5842]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:07 music sudo[5844]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:11:07 music sudo[5844]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:07 music sudo[5842]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:07 music sudo[5844]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "services"... Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "alsa_controller"... Jan 12 00:11:07 music sudo[5853]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 12 00:11:07 music sudo[5853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:07 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "wizard"... Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "networkfs"... Jan 12 00:11:07 music go-librespot[5819]: time="2026-01-12T00:11:07-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 12 00:11:07 music volumio[5803]: info: Starting Udev Watcher for removable devices Jan 12 00:11:07 music volumio[5803]: info: Ignoring mount for partition: boot Jan 12 00:11:07 music volumio[5803]: info: Ignoring mount for partition: volumio Jan 12 00:11:07 music volumio[5803]: info: Ignoring mount for partition: volumio_data Jan 12 00:11:07 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "volumio_command_line_client"... Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "upnp"... Jan 12 00:11:07 music volumio[5803]: info: [1768194667575] Starting Upmpd Daemon Jan 12 00:11:07 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "my_music"... Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "mpd"... Jan 12 00:11:07 music go-librespot[5819]: time="2026-01-12T00:11:07-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:07 music go-librespot[5819]: time="2026-01-12T00:11:07-05:00" level=debug msg="completed challenge" Jan 12 00:11:07 music go-librespot[5819]: time="2026-01-12T00:11:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:07 music volumio[5803]: info: Loading plugin "upnp_browser"... Jan 12 00:11:08 music sudo[5853]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:08 music volumio-remote-updater[22000]: [2026-01-12 00:11:08] [connect] Successful connection Jan 12 00:11:08 music go-librespot[5819]: time="2026-01-12T00:11:08-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 12 00:11:08 music go-librespot[5819]: time="2026-01-12T00:11:08-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:08 music go-librespot[5819]: time="2026-01-12T00:11:08-05:00" level=debug msg="completed challenge" Jan 12 00:11:08 music go-librespot[5819]: time="2026-01-12T00:11:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:09 music volumio[5803]: info: Starting UPNP Browser Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "alarm-clock"... Jan 12 00:11:09 music go-librespot[5819]: time="2026-01-12T00:11:09-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "airplay_emulation"... Jan 12 00:11:09 music volumio[5803]: info: Starting Shairport Sync Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "last_100"... Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "webradio"... Jan 12 00:11:09 music go-librespot[5819]: time="2026-01-12T00:11:09-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:09 music go-librespot[5819]: time="2026-01-12T00:11:09-05:00" level=debug msg="completed challenge" Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "i2s_dacs"... Jan 12 00:11:09 music volumio[5803]: info: I2S DAC not set, start Auto-detection Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "volumiodiscovery"... Jan 12 00:11:09 music go-librespot[5819]: time="2026-01-12T00:11:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:09 music go-librespot[5819]: time="2026-01-12T00:11: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 12 00:11:09 music volumio[5803]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:09 music volumio[5803]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:09 music volumio[5803]: *** WARNING *** For more information see Jan 12 00:11:09 music volumio[5803]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:09 music volumio[5803]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:09 music volumio[5803]: *** WARNING *** For more information see Jan 12 00:11:09 music node[5803]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:09 music node[5803]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:09 music node[5803]: *** WARNING *** For more information see Jan 12 00:11:09 music node[5803]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:09 music node[5803]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:09 music node[5803]: *** WARNING *** For more information see Jan 12 00:11:09 music volumio[5803]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 12 00:11:09 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:09 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:09 music volumio[5803]: info: Discovery: Started advertising with name: music Jan 12 00:11:09 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:09 music volumio[5803]: info: Loading plugin "spop"... Jan 12 00:11:10 music volumio[5803]: info: Loading plugin "outputs"... Jan 12 00:11:10 music volumio[5803]: info: Loading plugin "albumart"... Jan 12 00:11:10 music volumio[5803]: info: Plugin example_plugin is not enabled Jan 12 00:11:10 music volumio[5803]: info: Loading plugin "inputs"... Jan 12 00:11:11 music volumio[5803]: info: Loading plugin "updater_comm"... Jan 12 00:11:11 music volumio[5803]: info: Plugin mpdemulation is not enabled Jan 12 00:11:11 music volumio[5803]: info: Loading plugin "rest_api"... Jan 12 00:11:11 music volumio[5803]: info: Loading plugin "websocket"... Jan 12 00:11:11 music volumio[5803]: info: Starting Socket.io Server version 1.7.4 Jan 12 00:11:11 music volumio[5803]: info: Loading i18n strings for locale en Jan 12 00:11:11 music volumio[5803]: Updating browse sources language Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::initPlayerControls Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:11 music volumio[5803]: Express server listening on port 3000 Jan 12 00:11:11 music volumio[5803]: [Metrics] WebUI: 6s 554.31ms Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::resetVolumioState Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::getcurrentVolume Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: Volumio Network Manager: Network status updated: 1 Jan 12 00:11:11 music volumio-remote-updater[22000]: [2026-01-12 00:11:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768194668 101 Jan 12 00:11:11 music volumio[5880]: Forking 3 albumart workers Jan 12 00:11:11 music volumio[5803]: 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 12 00:11:11 music volumio[5803]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::pushState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::updateTrackBlock Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrackBlock Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:11:11 music volumio[5803]: info: Reloading queue from file Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::setRepeat null single undefined Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::pushState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::setRandom null Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::pushState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:11 music volumio[5803]: info: Setting Device type: Raspberry PI Jan 12 00:11:11 music volumio[5803]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:11:11 music volumio[5803]: info: CoreStateMachine::pushState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:11 music volumio[5803]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:11:11 music volumio[5803]: info: Discovery: Found device music Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:11:11 music volumio[5803]: info: Discovery: Found device music Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:11 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:11 music volumio[5803]: info: Completed loading Core Plugins Jan 12 00:11:11 music volumio[5803]: info: Preparing to generate the ALSA configuration file Jan 12 00:11:11 music volumio[5803]: info: Asound.conf file unchanged, so no further update is needed Jan 12 00:11:11 music volumio[5803]: info: Output device has changed, restarting MPD Jan 12 00:11:11 music volumio[5803]: info: Output device has changed, restarting Shairport Sync Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:11 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:12 music sudo[5939]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:11:12 music sudo[5939]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:12 music sudo[5936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:11:12 music sudo[5936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:12 music sudo[5936]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:12 music volumio[5803]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:12 music volumio[5803]: info: ___________ START PLUGINS ___________ Jan 12 00:11:12 music volumio[5803]: info: ControllerMpd::onStart: Initializing MPD Jan 12 00:11:12 music volumio[5803]: info: Creating MPD Configuration file Jan 12 00:11:12 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:12 music volumio[5803]: info: [1768194672148] CoreMusicLibrary::Adding element Media Servers Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:12 music sudo[5945]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:11:12 music sudo[5945]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:12 music sudo[5947]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:11:12 music sudo[5947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:12 music sudo[5945]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:12 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:11:12 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:11:12 music systemd[1]: mpd.service: Consumed 4.116s CPU time. Jan 12 00:11:12 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:11:12 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:11:12 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:11:12 music volumio[5803]: info: UPNP Browser: Client initialized successfully Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:12 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:11:12 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:11:12 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:11:12 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:11:12 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:11:12 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:11:12 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:11:12 music volumio[5803]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:12 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:12 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:11:12 music volumio[5803]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:12 music volumio[5803]: info: [1768194672373] CoreMusicLibrary::Adding element Last_100 Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:12 music volumio[5803]: info: [1768194672389] CoreMusicLibrary::Adding element Webradio Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:12 music volumio[5803]: info: Initializing BBC Radios Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:12 music sudo[5957]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 00:11:12 music sudo[5957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 00:11:12 music volumio[5803]: info: Creating Spotify config file Jan 12 00:11:12 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:12 music sudo[5957]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:13 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 12 00:11:13 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:13 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:13 music go-librespot[5977]: go-librespot daemon starting... Jan 12 00:11:13 music go-librespot[5978]: time="2026-01-12T00:11:13-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:13 music volumio[5898]: Starting albumart workers Jan 12 00:11:13 music volumio[5803]: info: Volumio Calling Home Jan 12 00:11:13 music volumio[5897]: Starting albumart workers Jan 12 00:11:13 music volumio[5896]: Starting albumart workers Jan 12 00:11:13 music go-librespot[5978]: time="2026-01-12T00:11:13-05:00" level=info msg="zeroconf server listening on port 37589" Jan 12 00:11:14 music volumio[5803]: info: MPD Permissions set Jan 12 00:11:14 music volumio[5803]: info: MPD Permissions set Jan 12 00:11:14 music volumio[5803]: info: Volumio called home Jan 12 00:11:14 music volumio[5803]: info: Spotify config file written Jan 12 00:11:14 music sudo[5992]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 12 00:11:14 music sudo[5992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:14 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 12 00:11:14 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 12 00:11:14 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:14 music volumio[5803]: 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 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:14 music go-librespot[6000]: go-librespot daemon starting... Jan 12 00:11:14 music sudo[5992]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music go-librespot[6003]: time="2026-01-12T00:11:14-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:14 music go-librespot[6003]: time="2026-01-12T00:11:14-05:00" level=debug msg="app state loaded" Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music go-librespot[6003]: time="2026-01-12T00:11:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:14 music volumio[5803]: info: No need to fix Spotify hosts Jan 12 00:11:14 music volumio[5803]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 12 00:11:14 music volumio[5803]: info: Starting Shairport Sync Jan 12 00:11:15 music volumio[5803]: info: Starting Shairport Sync Jan 12 00:11:15 music volumio[5803]: info: Starting Shairport Sync Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-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 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-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 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=info msg="zeroconf server listening on port 45117" Jan 12 00:11:15 music sudo[6033]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:15 music sudo[6033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:15 music sudo[6037]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:15 music sudo[6037]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:15 music sudo[6035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:15 music sudo[6035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:15 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 00:11:15 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:15 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:15 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 00:11:15 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:11:15 music systemd[1]: shairport-sync.service: Consumed 1.914s CPU time. Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=debug msg="obtained new client token: AABalcidr1euQrSJ9ZyFZQrPbSumEcTndDNEVgPTXclhnSH/DAVCI+OP+lxxTCMettoW1XCMr1/Oilf6Y5ILF6NAg0VheRldSyRyOpDR2DD+3W/KQmLk6fEXbC42eANviVQQSd9zWi7Nzp51MjK2+jkq8qsaX6DK+3f61A/bquvHHKRZmxwZ3HXBJbblPyjFO1NWIrNOhgd0cL2Vu/G6+xZRTsQL7cCr7PJkaH6mwcBJgNZ1swRC" Jan 12 00:11:15 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:11:15 music sudo[6037]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:15 music sudo[6033]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:15 music sudo[6035]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:15 music volumio[5803]: info: Shairport-Sync Started Jan 12 00:11:15 music volumio[5803]: Error adding Membership: Error: addMembership EINVAL Jan 12 00:11:15 music volumio[5803]: info: Shairport-Sync Started Jan 12 00:11:15 music volumio[5803]: info: Shairport-Sync Started Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=debug msg="completed challenge" Jan 12 00:11:15 music go-librespot[6003]: time="2026-01-12T00:11:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="completed challenge" Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:16 music mpd[5976]: 2026-01-12T00:11:16 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 00:11:16 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 00:11:16 music sudo[5947]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:16 music sudo[5939]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:16 music volumio[5803]: info: Completed starting Core Plugins Jan 12 00:11:16 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:16 music volumio[5803]: info: ----- MyVolumio plugins startup ---- Jan 12 00:11:16 music volumio[5803]: info: ------------------------------------------- Jan 12 00:11:16 music volumio[5803]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=debug msg="completed challenge" Jan 12 00:11:16 music go-librespot[6003]: time="2026-01-12T00:11:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:16 music volumio[5803]: error: MPD error: The expression evaluated to a falsy value: Jan 12 00:11:16 music volumio[5803]: assert.ok(self.idling) Jan 12 00:11:16 music volumio[5803]: error: The expression evaluated to a falsy value: Jan 12 00:11:16 music volumio[5803]: assert.ok(self.idling) Jan 12 00:11:16 music volumio[5803]: info: MPD running with PID5976 Jan 12 00:11:16 music volumio[5803]: ,establishing connection Jan 12 00:11:16 music volumio[5803]: error: updateQueue error: null Jan 12 00:11:16 music volumio[5803]: error: updateQueue error: null Jan 12 00:11:17 music go-librespot[6003]: time="2026-01-12T00:11:17-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:11:17 music go-librespot[6003]: time="2026-01-12T00:11:17-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:17 music go-librespot[6003]: time="2026-01-12T00:11:17-05:00" level=debug msg="completed challenge" Jan 12 00:11:17 music go-librespot[6003]: time="2026-01-12T00:11:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:17 music sudo[6077]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:11:17 music sudo[6077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:17 music sudo[6079]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:11:17 music sudo[6079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:17 music sudo[6077]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:17 music sudo[6079]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:17 music sudo[6083]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 12 00:11:17 music sudo[6083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:17 music sudo[6083]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:17 music volumio[5803]: info: Upmpdcli Daemon Started Jan 12 00:11:17 music volumio[5803]: info: go-librespot daemon successfully initialized Jan 12 00:11:18 music go-librespot[6003]: time="2026-01-12T00:11:18-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 12 00:11:18 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:18 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:18 music volumio[5803]: info: Listing playlists Jan 12 00:11:18 music volumio[5803]: info: Listing playlists Jan 12 00:11:18 music go-librespot[6003]: time="2026-01-12T00:11:18-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:18 music go-librespot[6003]: time="2026-01-12T00:11:18-05:00" level=debug msg="completed challenge" Jan 12 00:11:18 music go-librespot[6003]: time="2026-01-12T00:11:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:19 music go-librespot[6003]: time="2026-01-12T00:11:19-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:11:19 music go-librespot[6003]: time="2026-01-12T00:11:19-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:19 music go-librespot[6003]: time="2026-01-12T00:11:19-05:00" level=debug msg="completed challenge" Jan 12 00:11:19 music go-librespot[6003]: time="2026-01-12T00:11:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:19 music go-librespot[6003]: time="2026-01-12T00:11:19-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 12 00:11:19 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:19 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:19 music sudo[6086]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:11:19 music sudo[6086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:19 music sudo[6088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:11:19 music sudo[6088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:19 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 00:11:19 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 00:11:19 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 00:11:19 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 00:11:19 music sudo[6086]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:19 music sudo[6088]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:19 music volumio[5803]: info: Successfully started MPD Monitor Jan 12 00:11:19 music volumio[5803]: info: Successfully started MPD Monitor Jan 12 00:11:19 music mpd_monitor.sh[6091]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 00:11:20 music volumio[5803]: info: Initializing connection to go-librespot Websocket Jan 12 00:11:20 music volumio[5803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 00:11:21 music volumio[5803]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 12 00:11:22 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 12 00:11:22 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:22 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:22 music go-librespot[6095]: go-librespot daemon starting... Jan 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11:22-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11:22-05:00" level=debug msg="app state loaded" Jan 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11: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 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11: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 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11: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 12 00:11:22 music go-librespot[6096]: time="2026-01-12T00:11:22-05:00" level=info msg="zeroconf server listening on port 40987" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="obtained new client token: AADYi4x8jd1l+Kz1hpFp0JxzLdfT2ZxvznGmzpNGcvhd9AZ7wzuo80BFGVXR5y4egSsPF+nMX06wDoGKwqErtEb23LyiU0n08cG4DbIYwjVkT0qUKHdX/zdTUyhilvnO2Em6wpyVtZDGYpOpsTDOcljxUiNoZr+KAJBGon+7TqzQqK0+W5tk9aGgajTOqbe33pQ1V2r3zLR3FVhWD7Sg/QtZAfFP2sCOM650hN3UiPtcK9EE7zIa" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="completed challenge" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=debug msg="completed challenge" Jan 12 00:11:23 music go-librespot[6096]: time="2026-01-12T00:11:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:23 music volumio[5803]: info: Initializing connection to go-librespot Websocket Jan 12 00:11:24 music go-librespot[6096]: time="2026-01-12T00:11:24-05:00" level=debug msg="new websocket client" Jan 12 00:11:24 music volumio[5803]: info: Connection to go-librespot Websocket established Jan 12 00:11:24 music go-librespot[6096]: time="2026-01-12T00:11:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:24 music go-librespot[6096]: time="2026-01-12T00:11:24-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:24 music go-librespot[6096]: time="2026-01-12T00:11:24-05:00" level=debug msg="completed challenge" Jan 12 00:11:24 music go-librespot[6096]: time="2026-01-12T00:11:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 12 00:11:25 music volumio[5803]: info: Adding plugin bluetooth to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin multiroom to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin metavolumio to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin cd_controller to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 12 00:11:25 music volumio[5803]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 12 00:11:25 music go-librespot[6096]: time="2026-01-12T00:11:25-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 12 00:11:25 music go-librespot[6096]: time="2026-01-12T00:11:25-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:25 music go-librespot[6096]: time="2026-01-12T00:11:25-05:00" level=debug msg="completed challenge" Jan 12 00:11:25 music go-librespot[6096]: time="2026-01-12T00:11:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:26 music volumio[5803]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 12 00:11:26 music volumio[5803]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 12 00:11:26 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:26 music volumio[5803]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:26 music volumio[5803]: info: Starting MyVolumio Remote Streaming Endpoints Jan 12 00:11:26 music volumio[5803]: info: MyVolumio login type: Token Jan 12 00:11:26 music volumio[5803]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 12 00:11:26 music volumio[5803]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 12 00:11:26 music go-librespot[6096]: time="2026-01-12T00:11:26-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 12 00:11:26 music go-librespot[6096]: time="2026-01-12T00:11:26-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:26 music go-librespot[6096]: time="2026-01-12T00:11:26-05:00" level=debug msg="completed challenge" Jan 12 00:11:26 music go-librespot[6096]: time="2026-01-12T00:11:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:27 music volumio[5803]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 12 00:11:27 music volumio[5803]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 12 00:11:27 music volumio[5803]: info: Streaming services startup Jan 12 00:11:27 music volumio[5803]: info: Starting Streaming Daemon Jan 12 00:11:27 music sudo[6106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 12 00:11:27 music sudo[6106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:27 music volumio[5803]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 12 00:11:27 music sudo[6106]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:27 music volumio[5803]: info: Getting Spotify volume Jan 12 00:11:27 music volumio[5803]: error: Cannot start Volumio Streaming Daemon Jan 12 00:11:27 music volumio[5803]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 12 00:11:27 music volumio[5803]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 12 00:11:27 music volumio[5803]: 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 12 00:11:27 music go-librespot[6096]: time="2026-01-12T00:11:27-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:11:27 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:27 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:27 music go-librespot[6096]: time="2026-01-12T00:11:27-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:27 music go-librespot[6096]: time="2026-01-12T00:11:27-05:00" level=debug msg="completed challenge" Jan 12 00:11:27 music volumio[5803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 12 00:11:27 music volumio[5803]: SPOTIFY: SPOTIFY VOLUME undefined Jan 12 00:11:27 music volumio[5803]: SPOTIFY: VOLUMIO VOLUME 86 Jan 12 00:11:27 music volumio[5803]: info: Aligning Spotify Volume to Volumio Volume Jan 12 00:11:27 music volumio[5803]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:27 music volumio[5803]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:27 music volumio[5803]: info: Setting Spotify Volume from Volumio: 86 Jan 12 00:11:27 music go-librespot[6096]: time="2026-01-12T00:11:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:27 music go-librespot[6096]: time="2026-01-12T00:11: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 12 00:11:27 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:27 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:27 music volumio[5803]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:27 music volumio[5803]: Error: socket hang up Jan 12 00:11:27 music volumio[5803]: at connResetException (node:internal/errors:720:14) Jan 12 00:11:27 music volumio[5803]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 12 00:11:27 music volumio[5803]: at Socket.emit (node:events:526:35) Jan 12 00:11:27 music volumio[5803]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 12 00:11:27 music volumio[5803]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 12 00:11:27 music volumio[5803]: code: 'ECONNRESET', Jan 12 00:11:27 music volumio[5803]: response: undefined Jan 12 00:11:27 music volumio[5803]: } Jan 12 00:11:27 music volumio[5803]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:28 music sudo[6142]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 00:10' Jan 12 00:11:28 music sudo[6142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:28 music sudo[6142]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:28 music volumio-remote-updater[22000]: [2026-01-12 00:11:28] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 12 00:11:28 music volumio-remote-updater[22000]: [2026-01-12 00:11:28] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 12 00:11:28 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:28 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 12 00:11:28 music systemd[1]: volumio.service: Consumed 26.613s CPU time. Jan 12 00:11:28 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:28 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:29 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5855. Jan 12 00:11:29 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:29 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 12 00:11:29 music systemd[1]: volumio.service: Consumed 26.613s CPU time. Jan 12 00:11:29 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 12 00:11:29 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:30 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 12 00:11:30 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:30 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:30 music go-librespot[6169]: go-librespot daemon starting... Jan 12 00:11:30 music go-librespot[6170]: time="2026-01-12T00:11:30-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:30 music go-librespot[6170]: time="2026-01-12T00:11:30-05:00" level=debug msg="app state loaded" Jan 12 00:11:30 music go-librespot[6170]: time="2026-01-12T00:11:30-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:31 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:31 music volumio[6154]: info: ----- Volumio3 ---- Jan 12 00:11:31 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:31 music volumio[6154]: info: ----- System startup ---- Jan 12 00:11:31 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-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 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-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 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=info msg="zeroconf server listening on port 42813" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=debug msg="obtained new client token: AADzQ22Gy0bYLFlnIJOATl+dl5apzVVRx80sFX5N3BhemDpkyPdsD2AXk1XRzSp5Y6alw8LkzZgWo3CXlDU+Dk0Ie9xVyilLl2Y8or77llxFUK+q4Ty4BxUZ12IJqlUqXQxwpSMJwzY0iNUE1g96F7uE8U4/6OlAz8k4+SE0gq3wLmzkpMxe5lLy48H4CSVuUw1ASzsWD1uht/pYJ3HWZjyYfbrcLDOQwf82EyoNKTluHQM6aHB/cGg=" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=debug msg="completed challenge" Jan 12 00:11:31 music go-librespot[6170]: time="2026-01-12T00:11:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:31 music volumio[6154]: info: MYVOLUMIO Environment detected Jan 12 00:11:31 music volumio[6154]: info: Plugin folders cleanup Jan 12 00:11:31 music volumio[6154]: info: Scanning into folder /volumio/app/plugins/ Jan 12 00:11:31 music volumio[6154]: info: Scanning category audio_interface Jan 12 00:11:31 music volumio[6154]: info: Scanning category miscellanea Jan 12 00:11:31 music volumio[6154]: info: Scanning category music_service Jan 12 00:11:31 music volumio[6154]: info: Scanning category plugins.json Jan 12 00:11:31 music volumio[6154]: info: Scanning category system_controller Jan 12 00:11:31 music volumio[6154]: info: Scanning category user_interface Jan 12 00:11:32 music volumio[6154]: info: Scanning into folder /data/plugins/ Jan 12 00:11:32 music volumio[6154]: info: Scanning category music_service Jan 12 00:11:32 music volumio[6154]: info: Plugin folders cleanup completed Jan 12 00:11:32 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:32 music volumio[6154]: info: ----- Core plugins startup ---- Jan 12 00:11:32 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:32 music volumio[6154]: info: Loading plugins from folder /volumio/app/plugins/ Jan 12 00:11:32 music volumio[6154]: info: Adding plugin upnp to MyMusic Plugins Jan 12 00:11:32 music volumio[6154]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 12 00:11:32 music volumio[6154]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 12 00:11:32 music volumio[6154]: info: Loading plugins from folder /data/plugins/ Jan 12 00:11:32 music volumio[6154]: info: Loading plugin "system"... Jan 12 00:11:32 music volumio[6154]: info: Loading plugin "appearance"... Jan 12 00:11:32 music go-librespot[6170]: time="2026-01-12T00:11:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:32 music go-librespot[6170]: time="2026-01-12T00:11:32-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:32 music go-librespot[6170]: time="2026-01-12T00:11:32-05:00" level=debug msg="completed challenge" Jan 12 00:11:32 music go-librespot[6170]: time="2026-01-12T00:11:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:32 music go-librespot[6170]: time="2026-01-12T00:11:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=debug msg="completed challenge" Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "network"... Jan 12 00:11:33 music volumio[6154]: info: Refreshing Cached IP Addresses Jan 12 00:11:33 music sudo[6192]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:11:33 music sudo[6192]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:33 music sudo[6192]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:33 music sudo[6194]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:11:33 music sudo[6194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "services"... Jan 12 00:11:33 music sudo[6194]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "alsa_controller"... Jan 12 00:11:33 music sudo[6202]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 12 00:11:33 music sudo[6202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:33 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "wizard"... Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "networkfs"... Jan 12 00:11:33 music volumio[6154]: info: Starting Udev Watcher for removable devices Jan 12 00:11:33 music volumio[6154]: info: Ignoring mount for partition: boot Jan 12 00:11:33 music volumio[6154]: info: Ignoring mount for partition: volumio Jan 12 00:11:33 music volumio[6154]: info: Ignoring mount for partition: volumio_data Jan 12 00:11:33 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "volumio_command_line_client"... Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "upnp"... Jan 12 00:11:33 music volumio[6154]: info: [1768194693379] Starting Upmpd Daemon Jan 12 00:11:33 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "my_music"... Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "mpd"... Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=debug msg="completed challenge" Jan 12 00:11:33 music volumio-remote-updater[22000]: [2026-01-12 00:11:33] [connect] Successful connection Jan 12 00:11:33 music go-librespot[6170]: time="2026-01-12T00:11:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:33 music volumio[6154]: info: Loading plugin "upnp_browser"... Jan 12 00:11:33 music sudo[6202]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:34 music go-librespot[6170]: time="2026-01-12T00:11:34-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 12 00:11:34 music go-librespot[6170]: time="2026-01-12T00:11:34-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:34 music go-librespot[6170]: time="2026-01-12T00:11:34-05:00" level=debug msg="completed challenge" Jan 12 00:11:34 music go-librespot[6170]: time="2026-01-12T00:11:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:35 music volumio[6154]: info: Starting UPNP Browser Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "alarm-clock"... Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "airplay_emulation"... Jan 12 00:11:35 music volumio[6154]: info: Starting Shairport Sync Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "last_100"... Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "webradio"... Jan 12 00:11:35 music go-librespot[6170]: time="2026-01-12T00:11:35-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "i2s_dacs"... Jan 12 00:11:35 music volumio[6154]: info: I2S DAC not set, start Auto-detection Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "volumiodiscovery"... Jan 12 00:11:35 music go-librespot[6170]: time="2026-01-12T00:11:35-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:35 music go-librespot[6170]: time="2026-01-12T00:11:35-05:00" level=debug msg="completed challenge" Jan 12 00:11:35 music volumio[6154]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:35 music volumio[6154]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:35 music volumio[6154]: *** WARNING *** For more information see Jan 12 00:11:35 music volumio[6154]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:35 music volumio[6154]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:35 music volumio[6154]: *** WARNING *** For more information see Jan 12 00:11:35 music node[6154]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:35 music node[6154]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:35 music node[6154]: *** WARNING *** For more information see Jan 12 00:11:35 music node[6154]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:11:35 music node[6154]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:11:35 music node[6154]: *** WARNING *** For more information see Jan 12 00:11:35 music volumio[6154]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 12 00:11:35 music volumio[6154]: info: Discovery: Started advertising with name: music Jan 12 00:11:35 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:35 music volumio[6154]: info: Loading plugin "spop"... Jan 12 00:11:35 music go-librespot[6170]: time="2026-01-12T00:11:35-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:35 music go-librespot[6170]: time="2026-01-12T00:11: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 12 00:11:35 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:35 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "outputs"... Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "albumart"... Jan 12 00:11:36 music volumio[6154]: info: Plugin example_plugin is not enabled Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "inputs"... Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "updater_comm"... Jan 12 00:11:36 music volumio[6154]: info: Plugin mpdemulation is not enabled Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "rest_api"... Jan 12 00:11:36 music volumio[6154]: info: Loading plugin "websocket"... Jan 12 00:11:36 music volumio[6154]: info: Starting Socket.io Server version 1.7.4 Jan 12 00:11:36 music volumio[6154]: info: Loading i18n strings for locale en Jan 12 00:11:36 music volumio[6154]: Updating browse sources language Jan 12 00:11:36 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::initPlayerControls Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:37 music volumio[6154]: Express server listening on port 3000 Jan 12 00:11:37 music volumio[6154]: [Metrics] WebUI: 6s 613.64ms Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::resetVolumioState Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::getcurrentVolume Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: Volumio Network Manager: Network status updated: 1 Jan 12 00:11:37 music volumio-remote-updater[22000]: [2026-01-12 00:11:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768194693 101 Jan 12 00:11:37 music volumio[6154]: 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 12 00:11:37 music volumio[6227]: Forking 3 albumart workers Jan 12 00:11:37 music volumio[6154]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::pushState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::updateTrackBlock Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrackBlock Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:11:37 music volumio[6154]: info: Reloading queue from file Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::setRepeat null single undefined Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::pushState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::setRandom null Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::pushState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:37 music volumio[6154]: info: Setting Device type: Raspberry PI Jan 12 00:11:37 music volumio[6154]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:11:37 music volumio[6154]: info: CoreStateMachine::pushState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioPushState Jan 12 00:11:37 music volumio[6154]: info: Completed loading Core Plugins Jan 12 00:11:37 music volumio[6154]: info: Preparing to generate the ALSA configuration file Jan 12 00:11:37 music volumio[6154]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:11:37 music volumio[6154]: info: Discovery: Found device music Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:11:37 music volumio[6154]: info: Discovery: Found device music Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:37 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:37 music volumio[6154]: info: Asound.conf file unchanged, so no further update is needed Jan 12 00:11:37 music volumio[6154]: info: Output device has changed, restarting MPD Jan 12 00:11:37 music volumio[6154]: info: Output device has changed, restarting Shairport Sync Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:37 music sudo[6283]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:11:37 music sudo[6283]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:37 music sudo[6283]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:37 music sudo[6284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:11:37 music sudo[6284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:37 music volumio[6154]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:37 music volumio[6154]: info: ___________ START PLUGINS ___________ Jan 12 00:11:37 music volumio[6154]: info: ControllerMpd::onStart: Initializing MPD Jan 12 00:11:37 music volumio[6154]: info: Creating MPD Configuration file Jan 12 00:11:37 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:37 music volumio[6154]: info: [1768194697854] CoreMusicLibrary::Adding element Media Servers Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:37 music volumio[6154]: info: UPNP Browser: Client initialized successfully Jan 12 00:11:37 music sudo[6292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:11:37 music sudo[6292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:37 music sudo[6292]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:37 music sudo[6294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:11:37 music sudo[6294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:37 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:11:37 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:11:37 music systemd[1]: mpd.service: Consumed 4.090s CPU time. Jan 12 00:11:37 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:11:37 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:11:37 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:11:37 music volumio[6154]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:37 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:38 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:11:38 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:11:38 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:11:38 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:11:38 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:11:38 music volumio[6154]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:11:38 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:11:38 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:38 music volumio[6154]: info: [1768194698078] CoreMusicLibrary::Adding element Last_100 Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:11:38 music volumio[6154]: info: [1768194698084] CoreMusicLibrary::Adding element Webradio Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:11:38 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:38 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:11:38 music volumio[6154]: info: Initializing BBC Radios Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:38 music volumio[6154]: info: Creating Spotify config file Jan 12 00:11:38 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:38 music sudo[6308]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 00:11:38 music sudo[6308]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 00:11:38 music sudo[6308]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:38 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 12 00:11:38 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:38 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:38 music go-librespot[6324]: go-librespot daemon starting... Jan 12 00:11:38 music go-librespot[6325]: time="2026-01-12T00:11:38-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:39 music volumio[6154]: info: Volumio Calling Home Jan 12 00:11:39 music volumio[6242]: Starting albumart workers Jan 12 00:11:39 music volumio[6245]: Starting albumart workers Jan 12 00:11:39 music go-librespot[6325]: time="2026-01-12T00:11:39-05:00" level=info msg="zeroconf server listening on port 34325" Jan 12 00:11:39 music volumio[6243]: Starting albumart workers Jan 12 00:11:39 music volumio[6154]: info: MPD Permissions set Jan 12 00:11:39 music volumio[6154]: info: MPD Permissions set Jan 12 00:11:39 music volumio[6154]: info: Spotify config file written Jan 12 00:11:39 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:39 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:39 music sudo[6338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 12 00:11:39 music sudo[6338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:39 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 12 00:11:40 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 12 00:11:40 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:40 music volumio[6154]: 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 12 00:11:40 music volumio[6154]: info: Volumio called home Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:40 music go-librespot[6343]: go-librespot daemon starting... Jan 12 00:11:40 music sudo[6338]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=debug msg="app state loaded" Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:11:40 music volumio[6154]: info: No need to fix Spotify hosts Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-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 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-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 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-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 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=info msg="zeroconf server listening on port 36859" Jan 12 00:11:40 music volumio[6154]: info: Listing playlists Jan 12 00:11:40 music volumio[6154]: info: Listing playlists Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=debug msg="obtained new client token: AACwMS/1qAMX95YyLTIuKVf7ub5RdrdmQe9OP3z9vybleTDz7T/OYzG5LuRMaGSI2SSP/t4adECONryhGyOQq7zX0hj6jQ6K8jewv3XkIrEg//4nHaMvbko0y+W3BQ1n5U9ANYETY18IUi+GTx+Mdl/aZPsWYmPPuwXsQOEQrzv8aEiRrvyK6nBr0ZweIHzZJx/fjUdUydba2kMs0rPdzmY+2DO4GArNQHJIlBT3/EqcnnfpGk64qjQ=" Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:40 music volumio[6154]: info: Starting Shairport Sync Jan 12 00:11:40 music volumio[6154]: info: Starting Shairport Sync Jan 12 00:11:40 music volumio[6154]: info: Starting Shairport Sync Jan 12 00:11:40 music sudo[6384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:40 music volumio[6154]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 12 00:11:40 music sudo[6382]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:40 music sudo[6384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:40 music sudo[6382]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:40 music go-librespot[6345]: time="2026-01-12T00:11:40-05:00" level=debug msg="completed challenge" Jan 12 00:11:41 music sudo[6386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:11:41 music sudo[6386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:41 music go-librespot[6345]: time="2026-01-12T00:11:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:41 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 00:11:41 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 00:11:41 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:11:41 music systemd[1]: shairport-sync.service: Consumed 1.883s CPU time. Jan 12 00:11:41 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:41 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:41 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:11:41 music sudo[6386]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:41 music sudo[6382]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:41 music volumio[6154]: info: Shairport-Sync Started Jan 12 00:11:41 music sudo[6384]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:41 music volumio[6154]: Error adding Membership: Error: addMembership EINVAL Jan 12 00:11:41 music volumio[6154]: info: Shairport-Sync Started Jan 12 00:11:41 music volumio[6154]: info: Shairport-Sync Started Jan 12 00:11:41 music go-librespot[6345]: time="2026-01-12T00:11:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:41 music go-librespot[6345]: time="2026-01-12T00:11:41-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:41 music go-librespot[6345]: time="2026-01-12T00:11:41-05:00" level=debug msg="completed challenge" Jan 12 00:11:41 music go-librespot[6345]: time="2026-01-12T00:11:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:42 music go-librespot[6345]: time="2026-01-12T00:11:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:42 music go-librespot[6345]: time="2026-01-12T00:11:42-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:42 music go-librespot[6345]: time="2026-01-12T00:11:42-05:00" level=debug msg="completed challenge" Jan 12 00:11:42 music mpd[6323]: 2026-01-12T00:11:42 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 00:11:42 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 00:11:42 music sudo[6284]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:42 music sudo[6294]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:42 music go-librespot[6345]: time="2026-01-12T00:11:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:42 music volumio[6154]: info: Completed starting Core Plugins Jan 12 00:11:42 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:42 music volumio[6154]: info: ----- MyVolumio plugins startup ---- Jan 12 00:11:42 music volumio[6154]: info: ------------------------------------------- Jan 12 00:11:42 music volumio[6154]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 12 00:11:42 music volumio[6154]: error: MPD error: The expression evaluated to a falsy value: Jan 12 00:11:42 music volumio[6154]: assert.ok(self.idling) Jan 12 00:11:42 music volumio[6154]: error: The expression evaluated to a falsy value: Jan 12 00:11:42 music volumio[6154]: assert.ok(self.idling) Jan 12 00:11:42 music volumio[6154]: info: MPD running with PID6323 Jan 12 00:11:42 music volumio[6154]: ,establishing connection Jan 12 00:11:42 music volumio[6154]: error: updateQueue error: null Jan 12 00:11:42 music volumio[6154]: error: updateQueue error: null Jan 12 00:11:43 music go-librespot[6345]: time="2026-01-12T00:11:43-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:11:43 music go-librespot[6345]: time="2026-01-12T00:11:43-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:43 music go-librespot[6345]: time="2026-01-12T00:11:43-05:00" level=debug msg="completed challenge" Jan 12 00:11:43 music go-librespot[6345]: time="2026-01-12T00:11:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:43 music sudo[6426]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:11:43 music sudo[6426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:43 music sudo[6426]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:43 music sudo[6428]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:11:43 music sudo[6428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:43 music sudo[6428]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:43 music sudo[6431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 12 00:11:43 music sudo[6431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:43 music sudo[6431]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:43 music volumio[6154]: info: Upmpdcli Daemon Started Jan 12 00:11:43 music volumio[6154]: info: go-librespot daemon successfully initialized Jan 12 00:11:43 music go-librespot[6345]: time="2026-01-12T00:11:43-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 12 00:11:44 music go-librespot[6345]: time="2026-01-12T00:11:44-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:44 music go-librespot[6345]: time="2026-01-12T00:11:44-05:00" level=debug msg="completed challenge" Jan 12 00:11:44 music go-librespot[6345]: time="2026-01-12T00:11:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:44 music go-librespot[6345]: time="2026-01-12T00:11:44-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 12 00:11:45 music go-librespot[6345]: time="2026-01-12T00:11:45-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:45 music go-librespot[6345]: time="2026-01-12T00:11:45-05:00" level=debug msg="completed challenge" Jan 12 00:11:45 music go-librespot[6345]: time="2026-01-12T00:11:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:45 music go-librespot[6345]: time="2026-01-12T00:11:45-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 12 00:11:45 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:45 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:45 music sudo[6435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:11:45 music sudo[6435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:45 music sudo[6437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:11:45 music sudo[6437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:45 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 00:11:45 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 00:11:45 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 00:11:45 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 00:11:45 music sudo[6437]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:45 music sudo[6435]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:45 music mpd_monitor.sh[6440]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 00:11:45 music volumio[6154]: info: Successfully started MPD Monitor Jan 12 00:11:45 music volumio[6154]: info: Successfully started MPD Monitor Jan 12 00:11:46 music volumio[6154]: info: Initializing connection to go-librespot Websocket Jan 12 00:11:46 music volumio[6154]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 00:11:47 music volumio[6154]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 12 00:11:48 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 12 00:11:48 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:48 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:48 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:48 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:48 music go-librespot[6445]: go-librespot daemon starting... Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=debug msg="app state loaded" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-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 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-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 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-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 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=info msg="zeroconf server listening on port 41889" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=debug msg="obtained new client token: AAAVNijbuDI3LpGnTRAqvdxDZnkvkP9iGVs53rlmoO4wvWZJfzhMsMxkRy1h/+vGZYKN/aTD/QCbBtNhnGvctfsukUnB2yQw4Tu6fSLVz+oyJT+d1j0q2GtU8Y+6ocAlOzgIXbpehMds4hFgxbU8qkEd0QlmSQfUd6puOevKDlqOOKKH3ONPIFBAbVUG45iJFji5JMNR7/t3ixqLBxqIb4CxOM8TXlnjx44iWL2inQSbkDVy7ZgVYxQ=" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:48 music go-librespot[6446]: time="2026-01-12T00:11:48-05:00" level=debug msg="completed challenge" Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=debug msg="completed challenge" Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:49 music volumio[6154]: info: Initializing connection to go-librespot Websocket Jan 12 00:11:49 music go-librespot[6446]: time="2026-01-12T00:11:49-05:00" level=debug msg="new websocket client" Jan 12 00:11:49 music volumio[6154]: info: Connection to go-librespot Websocket established Jan 12 00:11:50 music go-librespot[6446]: time="2026-01-12T00:11:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:50 music go-librespot[6446]: time="2026-01-12T00:11:50-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:50 music go-librespot[6446]: time="2026-01-12T00:11:50-05:00" level=debug msg="completed challenge" Jan 12 00:11:50 music go-librespot[6446]: time="2026-01-12T00:11:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 12 00:11:50 music volumio[6154]: info: Adding plugin bluetooth to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin multiroom to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin metavolumio to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin cd_controller to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 12 00:11:50 music volumio[6154]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 12 00:11:51 music go-librespot[6446]: time="2026-01-12T00:11:51-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 12 00:11:51 music go-librespot[6446]: time="2026-01-12T00:11:51-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:51 music go-librespot[6446]: time="2026-01-12T00:11:51-05:00" level=debug msg="completed challenge" Jan 12 00:11:51 music go-librespot[6446]: time="2026-01-12T00:11:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:51 music volumio[6154]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 12 00:11:51 music volumio[6154]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 12 00:11:51 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:51 music volumio[6154]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:11:51 music volumio[6154]: info: Starting MyVolumio Remote Streaming Endpoints Jan 12 00:11:51 music volumio[6154]: info: MyVolumio login type: Token Jan 12 00:11:51 music volumio[6154]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 12 00:11:51 music volumio[6154]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 12 00:11:52 music go-librespot[6446]: time="2026-01-12T00:11:52-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 12 00:11:52 music go-librespot[6446]: time="2026-01-12T00:11:52-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:52 music go-librespot[6446]: time="2026-01-12T00:11:52-05:00" level=debug msg="completed challenge" Jan 12 00:11:52 music go-librespot[6446]: time="2026-01-12T00:11:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:52 music volumio[6154]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 12 00:11:52 music volumio[6154]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 12 00:11:52 music volumio[6154]: info: Streaming services startup Jan 12 00:11:52 music volumio[6154]: info: Starting Streaming Daemon Jan 12 00:11:52 music sudo[6456]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 12 00:11:52 music sudo[6456]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:52 music volumio[6154]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 12 00:11:52 music sudo[6456]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:52 music volumio[6154]: info: Getting Spotify volume Jan 12 00:11:53 music volumio[6154]: error: Cannot start Volumio Streaming Daemon Jan 12 00:11:53 music volumio[6154]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 12 00:11:53 music volumio[6154]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 12 00:11:53 music volumio[6154]: 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 12 00:11:53 music go-librespot[6446]: time="2026-01-12T00:11:53-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:11:53 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:53 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:53 music go-librespot[6446]: time="2026-01-12T00:11:53-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:53 music go-librespot[6446]: time="2026-01-12T00:11:53-05:00" level=debug msg="completed challenge" Jan 12 00:11:53 music volumio[6154]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 12 00:11:53 music volumio[6154]: SPOTIFY: SPOTIFY VOLUME undefined Jan 12 00:11:53 music volumio[6154]: SPOTIFY: VOLUMIO VOLUME 86 Jan 12 00:11:53 music volumio[6154]: info: Aligning Spotify Volume to Volumio Volume Jan 12 00:11:53 music volumio[6154]: info: CoreCommandRouter::volumioGetState Jan 12 00:11:53 music volumio[6154]: info: CorePlayQueue::getTrack 0 Jan 12 00:11:53 music volumio[6154]: info: Setting Spotify Volume from Volumio: 86 Jan 12 00:11:53 music go-librespot[6446]: time="2026-01-12T00:11:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:53 music go-librespot[6446]: time="2026-01-12T00:11:53-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 12 00:11:53 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:53 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:11:53 music volumio[6154]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:53 music volumio[6154]: Error: socket hang up Jan 12 00:11:53 music volumio[6154]: at connResetException (node:internal/errors:720:14) Jan 12 00:11:53 music volumio[6154]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 12 00:11:53 music volumio[6154]: at Socket.emit (node:events:526:35) Jan 12 00:11:53 music volumio[6154]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 12 00:11:53 music volumio[6154]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 12 00:11:53 music volumio[6154]: code: 'ECONNRESET', Jan 12 00:11:53 music volumio[6154]: response: undefined Jan 12 00:11:53 music volumio[6154]: } Jan 12 00:11:53 music volumio[6154]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:11:54 music sudo[6490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 00:10' Jan 12 00:11:54 music sudo[6490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:54 music sudo[6490]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:54 music volumio-remote-updater[22000]: [2026-01-12 00:11:54] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 12 00:11:54 music volumio-remote-updater[22000]: [2026-01-12 00:11:54] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 12 00:11:54 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:11:54 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 12 00:11:54 music systemd[1]: volumio.service: Consumed 26.804s CPU time. Jan 12 00:11:54 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:54 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:54 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5856. Jan 12 00:11:54 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 12 00:11:54 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 12 00:11:54 music systemd[1]: volumio.service: Consumed 26.804s CPU time. Jan 12 00:11:54 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 12 00:11:54 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 12 00:11:56 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 12 00:11:56 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:56 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:11:56 music go-librespot[6521]: go-librespot daemon starting... Jan 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-05:00" level=debug msg="app state loaded" Jan 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:11:56 music volumio[6506]: info: ------------------------------------------- Jan 12 00:11:56 music volumio[6506]: info: ----- Volumio3 ---- Jan 12 00:11:56 music volumio[6506]: info: ------------------------------------------- Jan 12 00:11:56 music volumio[6506]: info: ----- System startup ---- Jan 12 00:11:56 music volumio[6506]: info: ------------------------------------------- Jan 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-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 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-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 12 00:11:56 music go-librespot[6522]: time="2026-01-12T00:11:56-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 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=info msg="zeroconf server listening on port 42369" Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=debug msg="obtained new client token: AACnvuUpX0rmOGD0YwIUvdYanXNz3jXv/gP5E36kqKN+BEoD+YLMIecfgkEjq1fj5zTzgHGjmQOIJcHPWkeDTvOKGDor/awjKuhkaR4xQya+xuNwx4mRAQK9dtpK7Dgpk6uPCfJl2lGQQ3jWBVFP8kFpOwl+EB4NzHe8Q/o0ZttVMqPPKVz+vzHiTzUX70gqkLIQXKiyPyQF741wG94uQ/cynOVP3s1tBzXrPRzdY8xM2CTrtMIV" Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=debug msg="completed challenge" Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:57 music volumio[6506]: info: MYVOLUMIO Environment detected Jan 12 00:11:57 music volumio[6506]: info: Plugin folders cleanup Jan 12 00:11:57 music volumio[6506]: info: Scanning into folder /volumio/app/plugins/ Jan 12 00:11:57 music volumio[6506]: info: Scanning category audio_interface Jan 12 00:11:57 music volumio[6506]: info: Scanning category miscellanea Jan 12 00:11:57 music volumio[6506]: info: Scanning category music_service Jan 12 00:11:57 music volumio[6506]: info: Scanning category plugins.json Jan 12 00:11:57 music volumio[6506]: info: Scanning category system_controller Jan 12 00:11:57 music volumio[6506]: info: Scanning category user_interface Jan 12 00:11:57 music volumio[6506]: info: Scanning into folder /data/plugins/ Jan 12 00:11:57 music volumio[6506]: info: Scanning category music_service Jan 12 00:11:57 music volumio[6506]: info: Plugin folders cleanup completed Jan 12 00:11:57 music volumio[6506]: info: ------------------------------------------- Jan 12 00:11:57 music volumio[6506]: info: ----- Core plugins startup ---- Jan 12 00:11:57 music volumio[6506]: info: ------------------------------------------- Jan 12 00:11:57 music volumio[6506]: info: Loading plugins from folder /volumio/app/plugins/ Jan 12 00:11:57 music volumio[6506]: info: Adding plugin upnp to MyMusic Plugins Jan 12 00:11:57 music volumio[6506]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 12 00:11:57 music volumio[6506]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 12 00:11:57 music volumio[6506]: info: Loading plugins from folder /data/plugins/ Jan 12 00:11:57 music volumio[6506]: info: Loading plugin "system"... Jan 12 00:11:57 music volumio[6506]: info: Loading plugin "appearance"... Jan 12 00:11:57 music go-librespot[6522]: time="2026-01-12T00:11:57-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=debug msg="completed challenge" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=debug msg="completed challenge" Jan 12 00:11:58 music go-librespot[6522]: time="2026-01-12T00:11:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:58 music volumio[6506]: info: Loading plugin "network"... Jan 12 00:11:58 music volumio[6506]: info: Refreshing Cached IP Addresses Jan 12 00:11:59 music sudo[6544]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:11:59 music sudo[6544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:59 music sudo[6544]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:59 music sudo[6546]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:11:59 music sudo[6546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "services"... Jan 12 00:11:59 music sudo[6546]: pam_unix(sudo:session): session closed for user root Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "alsa_controller"... Jan 12 00:11:59 music sudo[6554]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 12 00:11:59 music sudo[6554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:11:59 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "wizard"... Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "networkfs"... Jan 12 00:11:59 music volumio[6506]: info: Starting Udev Watcher for removable devices Jan 12 00:11:59 music volumio[6506]: info: Ignoring mount for partition: boot Jan 12 00:11:59 music volumio[6506]: info: Ignoring mount for partition: volumio Jan 12 00:11:59 music volumio[6506]: info: Ignoring mount for partition: volumio_data Jan 12 00:11:59 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "volumio_command_line_client"... Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "upnp"... Jan 12 00:11:59 music volumio[6506]: info: [1768194719197] Starting Upmpd Daemon Jan 12 00:11:59 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "my_music"... Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "mpd"... Jan 12 00:11:59 music go-librespot[6522]: time="2026-01-12T00:11:59-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:11:59 music go-librespot[6522]: time="2026-01-12T00:11:59-05:00" level=debug msg="completed keyexchange" Jan 12 00:11:59 music go-librespot[6522]: time="2026-01-12T00:11:59-05:00" level=debug msg="completed challenge" Jan 12 00:11:59 music go-librespot[6522]: time="2026-01-12T00:11:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:11:59 music volumio-remote-updater[22000]: [2026-01-12 00:11:59] [connect] Successful connection Jan 12 00:11:59 music volumio[6506]: info: Loading plugin "upnp_browser"... Jan 12 00:11:59 music sudo[6554]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:00 music go-librespot[6522]: time="2026-01-12T00:12:00-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 12 00:12:00 music go-librespot[6522]: time="2026-01-12T00:12:00-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:12:00 music go-librespot[6522]: time="2026-01-12T00:12:00-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:00 music go-librespot[6522]: time="2026-01-12T00:12:00-05:00" level=debug msg="completed challenge" Jan 12 00:12:00 music go-librespot[6522]: time="2026-01-12T00:12:00-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:01 music volumio[6506]: info: Starting UPNP Browser Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "alarm-clock"... Jan 12 00:12:01 music go-librespot[6522]: time="2026-01-12T00:12:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:12:01 music go-librespot[6522]: time="2026-01-12T00:12:01-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:01 music go-librespot[6522]: time="2026-01-12T00:12:01-05:00" level=debug msg="completed challenge" Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "airplay_emulation"... Jan 12 00:12:01 music go-librespot[6522]: time="2026-01-12T00:12:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:01 music go-librespot[6522]: time="2026-01-12T00:12:01-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:01 music volumio[6506]: info: Starting Shairport Sync Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "last_100"... Jan 12 00:12:01 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:12:01 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "webradio"... Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "i2s_dacs"... Jan 12 00:12:01 music volumio[6506]: info: I2S DAC not set, start Auto-detection Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "volumiodiscovery"... Jan 12 00:12:01 music volumio[6506]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:12:01 music volumio[6506]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:12:01 music volumio[6506]: *** WARNING *** For more information see Jan 12 00:12:01 music volumio[6506]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:12:01 music volumio[6506]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:12:01 music volumio[6506]: *** WARNING *** For more information see Jan 12 00:12:01 music node[6506]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 12 00:12:01 music node[6506]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:12:01 music node[6506]: *** WARNING *** For more information see Jan 12 00:12:01 music node[6506]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 12 00:12:01 music node[6506]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 12 00:12:01 music node[6506]: *** WARNING *** For more information see Jan 12 00:12:01 music volumio[6506]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 12 00:12:01 music volumio[6506]: info: Discovery: Started advertising with name: music Jan 12 00:12:01 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 12 00:12:01 music volumio[6506]: info: Loading plugin "spop"... Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "outputs"... Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "albumart"... Jan 12 00:12:02 music volumio[6506]: info: Plugin example_plugin is not enabled Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "inputs"... Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "updater_comm"... Jan 12 00:12:02 music volumio[6506]: info: Plugin mpdemulation is not enabled Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "rest_api"... Jan 12 00:12:02 music volumio[6506]: info: Loading plugin "websocket"... Jan 12 00:12:02 music volumio[6506]: info: Starting Socket.io Server version 1.7.4 Jan 12 00:12:02 music volumio[6506]: info: Loading i18n strings for locale en Jan 12 00:12:02 music volumio[6506]: Updating browse sources language Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::initPlayerControls Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:02 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:12:03 music volumio[6506]: Express server listening on port 3000 Jan 12 00:12:03 music volumio[6506]: [Metrics] WebUI: 6s 661.23ms Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::resetVolumioState Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::getcurrentVolume Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: Volumio Network Manager: Network status updated: 1 Jan 12 00:12:03 music volumio[6579]: Forking 3 albumart workers Jan 12 00:12:03 music volumio[6506]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::pushState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioPushState Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::updateTrackBlock Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrackBlock Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioRetrievevolume Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioGetState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio-remote-updater[22000]: [2026-01-12 00:12:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768194719 101 Jan 12 00:12:03 music volumio[6506]: 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 12 00:12:03 music volumio[6506]: info: Reloading queue from file Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::setRepeat null single undefined Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::pushState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioPushState Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::setRandom null Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::pushState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioPushState Jan 12 00:12:03 music volumio[6506]: info: Setting Device type: Raspberry PI Jan 12 00:12:03 music volumio[6506]: info: Listing playlists Jan 12 00:12:03 music volumio[6506]: info: Listing playlists Jan 12 00:12:03 music volumio[6506]: info: VolumeController:: Volume=86 Mute =false Jan 12 00:12:03 music volumio[6506]: info: CoreStateMachine::pushState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioPushState Jan 12 00:12:03 music volumio[6506]: info: Completed loading Core Plugins Jan 12 00:12:03 music volumio[6506]: info: Preparing to generate the ALSA configuration file Jan 12 00:12:03 music volumio[6506]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:12:03 music volumio[6506]: info: Discovery: Found device music Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioGetState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 12 00:12:03 music volumio[6506]: info: Discovery: Found device music Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioGetState Jan 12 00:12:03 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:03 music volumio[6506]: info: Asound.conf file unchanged, so no further update is needed Jan 12 00:12:03 music volumio[6506]: info: Output device has changed, restarting MPD Jan 12 00:12:03 music volumio[6506]: info: Output device has changed, restarting Shairport Sync Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:03 music sudo[6636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:12:03 music sudo[6634]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:12:03 music sudo[6634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:03 music sudo[6636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:03 music sudo[6634]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:03 music volumio[6506]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:12:03 music volumio[6506]: info: ___________ START PLUGINS ___________ Jan 12 00:12:03 music volumio[6506]: info: ControllerMpd::onStart: Initializing MPD Jan 12 00:12:03 music volumio[6506]: info: Creating MPD Configuration file Jan 12 00:12:03 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:12:03 music volumio[6506]: info: [1768194723748] CoreMusicLibrary::Adding element Media Servers Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:12:03 music volumio[6506]: info: UPNP Browser: Client initialized successfully Jan 12 00:12:03 music sudo[6644]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 00:12:03 music sudo[6644]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:03 music sudo[6644]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:03 music sudo[6646]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 00:12:03 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:03 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:12:03 music systemd[1]: mpd.service: Consumed 4.165s CPU time. Jan 12 00:12:03 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:12:03 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:12:03 music sudo[6646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:03 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:12:03 music volumio[6506]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:03 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:12:03 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:12:03 music systemd[1]: mpd.service: Deactivated successfully. Jan 12 00:12:03 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 12 00:12:03 music systemd[1]: mpd.socket: Deactivated successfully. Jan 12 00:12:03 music volumio[6506]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 00:12:03 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 12 00:12:03 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:12:03 music volumio[6506]: info: [1768194723935] CoreMusicLibrary::Adding element Last_100 Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:12:03 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 12 00:12:03 music volumio[6506]: info: [1768194723953] CoreMusicLibrary::Adding element Webradio Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 00:12:03 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 12 00:12:03 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:12:03 music volumio[6506]: info: Initializing BBC Radios Jan 12 00:12:04 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 12 00:12:04 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:04 music volumio[6506]: info: Creating Spotify config file Jan 12 00:12:04 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:04 music sudo[6660]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 00:12:04 music sudo[6660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 12 00:12:04 music sudo[6660]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:04 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 12 00:12:04 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:04 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:04 music go-librespot[6676]: go-librespot daemon starting... Jan 12 00:12:04 music go-librespot[6677]: time="2026-01-12T00:12:04-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:12:04 music go-librespot[6677]: time="2026-01-12T00:12:04-05:00" level=info msg="zeroconf server listening on port 38313" Jan 12 00:12:04 music volumio[6506]: info: Volumio Calling Home Jan 12 00:12:05 music volumio[6595]: Starting albumart workers Jan 12 00:12:05 music volumio[6596]: Starting albumart workers Jan 12 00:12:05 music volumio[6598]: Starting albumart workers Jan 12 00:12:05 music volumio[6506]: info: MPD Permissions set Jan 12 00:12:05 music volumio[6506]: info: MPD Permissions set Jan 12 00:12:05 music volumio[6506]: info: Spotify config file written Jan 12 00:12:05 music volumio[6506]: 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 12 00:12:05 music sudo[6690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music sudo[6690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 12 00:12:05 music systemd[1]: go-librespot-daemon.service: Killing process 6681 (go-librespot) with signal SIGKILL. Jan 12 00:12:05 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 12 00:12:05 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 00:12:05 music volumio[6506]: info: No need to fix Spotify hosts Jan 12 00:12:05 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:05 music go-librespot[6704]: go-librespot daemon starting... Jan 12 00:12:05 music sudo[6690]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="app state loaded" Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-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 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-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 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=info msg="zeroconf server listening on port 38593" Jan 12 00:12:06 music volumio[6506]: info: Volumio called home Jan 12 00:12:06 music volumio[6506]: info: Starting Shairport Sync Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="obtained new client token: AAAm/MxHwHKOZIXwsmqepMzKHTJMfMxgtc7s9H29iJaTB0MoiyvTWYMRarZ0wpoONLUtYtwY+Zt3v8Jsd00DR1Do4WJ3zM7dyUxRp9/tlgvraJedKcx5AwmInaNXwlAwFsXGiWhA5jtjWGFXmM1fk0bhnL1DHjlia+fvl03WiZPmYW6M8AFuiCOpoFmWHricQxiThDs83yqXSzye1mAqwhXMhh85kAjlQPWKKaHXCXqTZvcgg57nXy0=" Jan 12 00:12:06 music volumio[6506]: info: Starting Shairport Sync Jan 12 00:12:06 music volumio[6506]: info: Starting Shairport Sync Jan 12 00:12:06 music sudo[6733]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:12:06 music sudo[6733]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:06 music sudo[6737]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:12:06 music sudo[6737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:06 music volumio[6506]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 12 00:12:06 music sudo[6735]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:12:06 music sudo[6735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:06 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 00:12:06 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 00:12:06 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:12:06 music systemd[1]: shairport-sync.service: Consumed 1.883s CPU time. Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=debug msg="completed challenge" Jan 12 00:12:06 music volumio[6506]: info: CoreCommandRouter::volumioGetState Jan 12 00:12:06 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:06 music go-librespot[6705]: time="2026-01-12T00:12:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:06 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:12:06 music sudo[6733]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:06 music volumio[6506]: info: Shairport-Sync Started Jan 12 00:12:06 music sudo[6735]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:06 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 12 00:12:06 music volumio[6506]: Error adding Membership: Error: addMembership EINVAL Jan 12 00:12:06 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 12 00:12:06 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:12:06 music volumio[6506]: info: Shairport-Sync Started Jan 12 00:12:06 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 12 00:12:06 music sudo[6737]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:06 music volumio[6506]: info: Shairport-Sync Started Jan 12 00:12:07 music go-librespot[6705]: time="2026-01-12T00:12:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 12 00:12:07 music go-librespot[6705]: time="2026-01-12T00:12:07-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:07 music go-librespot[6705]: time="2026-01-12T00:12:07-05:00" level=debug msg="completed challenge" Jan 12 00:12:07 music go-librespot[6705]: time="2026-01-12T00:12:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="completed challenge" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:08 music volumio[6506]: info: CoreCommandRouter::volumioGetState Jan 12 00:12:08 music volumio[6506]: info: CorePlayQueue::getTrack 0 Jan 12 00:12:08 music mpd[6675]: 2026-01-12T00:12:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 00:12:08 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 12 00:12:08 music sudo[6646]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:08 music sudo[6636]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:08 music volumio[6506]: info: Completed starting Core Plugins Jan 12 00:12:08 music volumio[6506]: info: ------------------------------------------- Jan 12 00:12:08 music volumio[6506]: info: ----- MyVolumio plugins startup ---- Jan 12 00:12:08 music volumio[6506]: info: ------------------------------------------- Jan 12 00:12:08 music volumio[6506]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 12 00:12:08 music volumio[6506]: error: MPD error: The expression evaluated to a falsy value: Jan 12 00:12:08 music volumio[6506]: assert.ok(self.idling) Jan 12 00:12:08 music volumio[6506]: error: The expression evaluated to a falsy value: Jan 12 00:12:08 music volumio[6506]: assert.ok(self.idling) Jan 12 00:12:08 music volumio[6506]: info: MPD running with PID6675 Jan 12 00:12:08 music volumio[6506]: ,establishing connection Jan 12 00:12:08 music volumio[6506]: error: updateQueue error: null Jan 12 00:12:08 music volumio[6506]: error: updateQueue error: null Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=debug msg="completed challenge" Jan 12 00:12:08 music go-librespot[6705]: time="2026-01-12T00:12:08-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:09 music sudo[6778]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 12 00:12:09 music sudo[6778]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:09 music sudo[6778]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:09 music sudo[6780]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 12 00:12:09 music sudo[6780]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:09 music sudo[6780]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:09 music sudo[6783]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 12 00:12:09 music sudo[6783]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:09 music sudo[6783]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:09 music volumio[6506]: info: Upmpdcli Daemon Started Jan 12 00:12:09 music volumio[6506]: info: go-librespot daemon successfully initialized Jan 12 00:12:09 music go-librespot[6705]: time="2026-01-12T00:12:09-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 12 00:12:09 music go-librespot[6705]: time="2026-01-12T00:12:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 12 00:12:10 music go-librespot[6705]: time="2026-01-12T00:12:10-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:12:10 music go-librespot[6705]: time="2026-01-12T00:12:10-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:10 music go-librespot[6705]: time="2026-01-12T00:12:10-05:00" level=debug msg="completed challenge" Jan 12 00:12:10 music go-librespot[6705]: time="2026-01-12T00:12:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:10 music go-librespot[6705]: time="2026-01-12T00:12:10-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:10 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:12:10 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:12:11 music sudo[6787]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:12:11 music sudo[6787]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:11 music sudo[6789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 12 00:12:11 music sudo[6789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:11 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 00:12:11 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 00:12:11 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 00:12:11 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 00:12:11 music sudo[6787]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:11 music mpd_monitor.sh[6792]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 00:12:11 music volumio[6506]: info: Successfully started MPD Monitor Jan 12 00:12:11 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 12 00:12:11 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 12 00:12:11 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 12 00:12:11 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 12 00:12:11 music sudo[6789]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:11 music volumio[6506]: info: Successfully started MPD Monitor Jan 12 00:12:11 music mpd_monitor.sh[6795]: MPD Monitor Service: Starting MPD Monitor Service Jan 12 00:12:12 music volumio[6506]: info: Initializing connection to go-librespot Websocket Jan 12 00:12:12 music volumio[6506]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 00:12:13 music volumio[6506]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 12 00:12:13 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 12 00:12:13 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:13 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 12 00:12:13 music go-librespot[6799]: go-librespot daemon starting... Jan 12 00:12:13 music go-librespot[6800]: time="2026-01-12T00:12:13-05:00" level=info msg="running go-librespot 0.6.2" Jan 12 00:12:13 music go-librespot[6800]: time="2026-01-12T00:12:13-05:00" level=debug msg="app state loaded" Jan 12 00:12:13 music go-librespot[6800]: time="2026-01-12T00:12:13-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-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 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-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 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-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 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=info msg="zeroconf server listening on port 42319" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=debug msg="obtained new client token: AADt59j5ECOFpsNmhL/lfethips0MyXibIzJ6zB0GddF+diweHbknfb87lUmTqHZAAdqAptZMPFC+C4GBmXbbIEgp5vsoON2p3+LBzStbE59Q31qc+e361oLP4wj6lV8iAouHKuWebWRH9RIFFStKXNWrxV6uQVWVeaGTySMQghxDhBWY6UbndljXKWzKml36rA2XxkerQSWyDIUB59cjpkoYythiT4Jde/K+w5uNkrjvToS2c6A8NM=" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=debug msg="completed challenge" Jan 12 00:12:14 music go-librespot[6800]: time="2026-01-12T00:12:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-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 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="completed challenge" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:15 music volumio[6506]: info: Initializing connection to go-librespot Websocket Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="new websocket client" Jan 12 00:12:15 music volumio[6506]: info: Connection to go-librespot Websocket established Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=debug msg="completed challenge" Jan 12 00:12:15 music go-librespot[6800]: time="2026-01-12T00:12:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:16 music go-librespot[6800]: time="2026-01-12T00:12:16-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 12 00:12:16 music go-librespot[6800]: time="2026-01-12T00:12:16-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:16 music go-librespot[6800]: time="2026-01-12T00:12:16-05:00" level=debug msg="completed challenge" Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 12 00:12:16 music volumio[6506]: info: Adding plugin bluetooth to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin multiroom to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin metavolumio to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin cd_controller to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 12 00:12:16 music volumio[6506]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 12 00:12:16 music go-librespot[6800]: time="2026-01-12T00:12:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:17 music go-librespot[6800]: time="2026-01-12T00:12:17-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 12 00:12:17 music go-librespot[6800]: time="2026-01-12T00:12:17-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:17 music go-librespot[6800]: time="2026-01-12T00:12:17-05:00" level=debug msg="completed challenge" Jan 12 00:12:17 music volumio[6506]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 12 00:12:17 music volumio[6506]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 12 00:12:17 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:17 music volumio[6506]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 00:12:17 music volumio[6506]: info: Starting MyVolumio Remote Streaming Endpoints Jan 12 00:12:17 music volumio[6506]: info: MyVolumio login type: Token Jan 12 00:12:17 music go-librespot[6800]: time="2026-01-12T00:12:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:17 music volumio[6506]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 12 00:12:17 music volumio[6506]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 12 00:12:18 music go-librespot[6800]: time="2026-01-12T00:12:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 12 00:12:18 music go-librespot[6800]: time="2026-01-12T00:12:18-05:00" level=debug msg="completed keyexchange" Jan 12 00:12:18 music go-librespot[6800]: time="2026-01-12T00:12:18-05:00" level=debug msg="completed challenge" Jan 12 00:12:18 music go-librespot[6800]: time="2026-01-12T00:12:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 12 00:12:18 music go-librespot[6800]: time="2026-01-12T00:12:18-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 12 00:12:18 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 12 00:12:18 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 12 00:12:18 music volumio[6506]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 12 00:12:18 music volumio[6506]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 12 00:12:18 music volumio[6506]: info: Streaming services startup Jan 12 00:12:18 music volumio[6506]: info: Starting Streaming Daemon Jan 12 00:12:18 music sudo[6810]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 12 00:12:18 music sudo[6810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 12 00:12:18 music volumio[6506]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 12 00:12:18 music sudo[6810]: pam_unix(sudo:session): session closed for user root Jan 12 00:12:18 music volumio[6506]: info: Getting Spotify volume Jan 12 00:12:18 music volumio[6506]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:12:18 music volumio[6506]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 00:12:18 music volumio[6506]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 12 00:12:18 music volumio[6506]: errno: -111, Jan 12 00:12:18 music volumio[6506]: code: 'ECONNREFUSED', Jan 12 00:12:18 music volumio[6506]: syscall: 'connect', Jan 12 00:12:18 music volumio[6506]: address: '127.0.0.1', Jan 12 00:12:18 music volumio[6506]: port: 9879, Jan 12 00:12:18 music volumio[6506]: response: undefined Jan 12 00:12:18 music volumio[6506]: } Jan 12 00:12:18 music volumio[6506]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 00:12:19 music sudo[6845]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-12 00:11' Jan 12 00:12:19 music sudo[6845]: 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"