Jan 27 17:02:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 27 17:02:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:01 volumio go-librespot[25811]: go-librespot daemon starting... Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=debug msg="app state loaded" Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:01 volumio go-librespot[25812]: time="2026-01-27T17:02:01+07:00" level=info msg="zeroconf server listening on port 34211" Jan 27 17:02:02 volumio go-librespot[25812]: time="2026-01-27T17:02:02+07:00" level=debug msg="obtained new client token: AABYQAIgsqK6nxXdv4J5aFhdh3OetSeb7T56kkyy40FjgHEDXfPsZSZEXHlyIjgajpDX3PLWCKADs/eZLTpbTeoZTrpK3lkeLTc05ak1YmHs+8Vf1GnqIXICcXLlwYOdpKqpABQGNRJ205R/VTEi3zBmjQB5lhGxYHt8x06+OuSHUSRdHDXXj8foeuEPZoyP2Sm8jLx0qy6xvZ/5cx5uzM5YFYQxx2jkoi9acHZHmpP20tgrLZLa3cld" Jan 27 17:02:02 volumio volumio[25722]: info: Loading plugin "ytmusic"... Jan 27 17:02:02 volumio go-librespot[25812]: time="2026-01-27T17:02:02+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:02 volumio go-librespot[25812]: time="2026-01-27T17:02:02+07:00" level=debug msg="completed keyexchange" Jan 27 17:02:02 volumio go-librespot[25812]: time="2026-01-27T17:02:02+07:00" level=debug msg="completed challenge" Jan 27 17:02:02 volumio go-librespot[25812]: time="2026-01-27T17:02:02+07: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 27 17:02:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:03 volumio volumio-remote-updater[628]: [2026-01-27 17:02:03] [connect] Successful connection Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "outputs"... Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "albumart"... Jan 27 17:02:03 volumio volumio[25722]: info: Plugin example_plugin is not enabled Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "inputs"... Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "updater_comm"... Jan 27 17:02:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:03 volumio volumio[25722]: info: Plugin mpdemulation is not enabled Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "rest_api"... Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "websocket"... Jan 27 17:02:03 volumio volumio[25722]: info: Starting Socket.io Server version 1.7.4 Jan 27 17:02:03 volumio volumio[25722]: info: Loading plugin "RoonBridge"... Jan 27 17:02:04 volumio volumio[25722]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 17:02:04 volumio volumio[25722]: info: Loading i18n strings for locale en Jan 27 17:02:04 volumio volumio[25722]: Updating browse sources language Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::initPlayerControls Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:04 volumio volumio[25722]: Express server listening on port 3000 Jan 27 17:02:04 volumio volumio[25722]: [Metrics] WebUI: 16s 87.62ms Jan 27 17:02:04 volumio volumio[25833]: Forking 3 albumart workers Jan 27 17:02:04 volumio volumio[25722]: info: CoreStateMachine::resetVolumioState Jan 27 17:02:04 volumio volumio[25722]: info: CoreStateMachine::getcurrentVolume Jan 27 17:02:04 volumio volumio[25722]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:04 volumio sudo[25859]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:02:04 volumio sudo[25859]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:04 volumio sudo[25861]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:02:04 volumio sudo[25861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:04 volumio sudo[25859]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:04 volumio sudo[25861]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:04 volumio volumio[25722]: info: Volumio Network Manager: Network status updated: 1 Jan 27 17:02:05 volumio volumio[25722]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::pushState Jan 27 17:02:05 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::updateTrackBlock Jan 27 17:02:05 volumio volumio[25722]: info: CorePlayQueue::getTrackBlock Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:05 volumio volumio-remote-updater[628]: [2026-01-27 17:02:05] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769508123 101 Jan 27 17:02:05 volumio volumio[25722]: 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 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:05 volumio volumio[25722]: info: Reloading queue from file Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::setRepeat null single undefined Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::pushState Jan 27 17:02:05 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::setRandom null Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::pushState Jan 27 17:02:05 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:05 volumio volumio[25722]: info: Setting Device type: Raspberry PI Jan 27 17:02:05 volumio volumio[25722]: info: Completed loading Core Plugins Jan 27 17:02:05 volumio volumio[25722]: info: Preparing to generate the ALSA configuration file Jan 27 17:02:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:05 volumio volumio[25722]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:05 volumio volumio[25722]: info: CoreStateMachine::pushState Jan 27 17:02:05 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:05 volumio volumio[25722]: info: Asound.conf file unchanged, so no further update is needed Jan 27 17:02:05 volumio volumio[25722]: info: Output device has changed, restarting MPD Jan 27 17:02:05 volumio sudo[25893]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 17:02:05 volumio sudo[25893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:05 volumio volumio[25722]: info: Output device has changed, restarting Shairport Sync Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:05 volumio sudo[25895]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:02:05 volumio sudo[25895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Jan 27 17:02:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:05 volumio sudo[25895]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:05 volumio sudo[25898]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:02:05 volumio sudo[25898]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:05 volumio volumio[25722]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:05 volumio volumio[25722]: info: ___________ START PLUGINS ___________ Jan 27 17:02:05 volumio go-librespot[25902]: go-librespot daemon starting... Jan 27 17:02:05 volumio sudo[25893]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:05 volumio volumio[25722]: info: ControllerMpd::onStart: Initializing MPD Jan 27 17:02:05 volumio volumio[25722]: info: Creating MPD Configuration file Jan 27 17:02:05 volumio go-librespot[25906]: time="2026-01-27T17:02:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:05 volumio go-librespot[25906]: time="2026-01-27T17:02:05+07:00" level=debug msg="app state loaded" Jan 27 17:02:05 volumio go-librespot[25906]: time="2026-01-27T17:02:05+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:05 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:05 volumio volumio[25722]: info: [1769508125941] CoreMusicLibrary::Adding element Media Servers Jan 27 17:02:05 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:06 volumio sudo[25915]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:02:06 volumio sudo[25915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:06 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:02:06 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:02:06 volumio systemd[1]: mpd.service: Consumed 7.125s CPU time. Jan 27 17:02:06 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:02:06 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:02:06 volumio volumio[25722]: info: UPNP Browser: Client initialized successfully Jan 27 17:02:06 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:02:06 volumio sudo[25913]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:02:06 volumio sudo[25913]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:06 volumio sudo[25913]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:06 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:02:06 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:06 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:02:06 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:02:06 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:02:06 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:02:06 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:02:06 volumio volumio[25722]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:06 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:06 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:02:06 volumio volumio[25722]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:06 volumio volumio[25722]: info: [1769508126544] CoreMusicLibrary::Adding element Last_100 Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:06 volumio volumio[25722]: info: [1769508126598] CoreMusicLibrary::Adding element Webradio Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:02:06 volumio volumio[25722]: info: Initializing BBC Radios Jan 27 17:02:06 volumio go-librespot[25906]: time="2026-01-27T17:02:06+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:06 volumio go-librespot[25906]: time="2026-01-27T17:02:06+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:06 volumio go-librespot[25906]: time="2026-01-27T17:02:06+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:06 volumio go-librespot[25906]: time="2026-01-27T17:02:06+07:00" level=info msg="zeroconf server listening on port 46651" Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:02:06 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:06 volumio sudo[25927]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 17:02:06 volumio sudo[25927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 17:02:06 volumio go-librespot[25906]: time="2026-01-27T17:02:06+07:00" level=debug msg="obtained new client token: AAANSakQj/1kNX4iKXnewp0eF7VOKHXnNESUHOldMX9gJ8NogXdw7fmU4Fkq2SQgGPsOSFSXmw1O7nXimPuS0bWUZrSrm9Ku0JSLqmatSRVlZk9HrwvN9kJPiQix2MUFJRqfMBxZdtIbLgT2M49wYmc8i2Nw5f5BvE6zkMf1xAGr1S6brgJEgPAaBtScbDPJb/zvU8IJUyWHNzuSrCyOHy+ztIkVcLsxzx3eXe78+G6vA72LDKy3StdryoA=" Jan 27 17:02:06 volumio sudo[25927]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:07 volumio volumio[25722]: info: Creating Spotify config file Jan 27 17:02:07 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:07 volumio go-librespot[25906]: time="2026-01-27T17:02:07+07:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 27 17:02:07 volumio go-librespot[25906]: time="2026-01-27T17:02:07+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 17:02:07 volumio go-librespot[25906]: time="2026-01-27T17:02:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:07 volumio volumio[25849]: Starting albumart workers Jan 27 17:02:08 volumio volumio[25846]: Starting albumart workers Jan 27 17:02:08 volumio volumio[25847]: Starting albumart workers Jan 27 17:02:08 volumio volumio[25722]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:08 volumio volumio[25722]: info: [1769508128380] CoreMusicLibrary::Adding element YouTube Music Jan 27 17:02:08 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:08 volumio volumio[25722]: Cannot find translation for source YouTube Music Jan 27 17:02:08 volumio volumio[25722]: info: Volumio Calling Home Jan 27 17:02:08 volumio sudo[25947]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 17:02:08 volumio sudo[25947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:08 volumio sudo[25947]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:09 volumio volumio[25722]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:02:09 volumio volumio[25722]: info: Discovery: Found device Volumio Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:09 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:09 volumio volumio[25722]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:02:09 volumio volumio[25722]: info: Discovery: Found device Volumio Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:09 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:09 volumio volumio[25722]: info: MPD Permissions set Jan 27 17:02:09 volumio volumio[25722]: info: MPD Permissions set Jan 27 17:02:09 volumio volumio[25722]: info: Upmpdcli Daemon Started Jan 27 17:02:09 volumio volumio[25722]: info: Volumio called home Jan 27 17:02:09 volumio volumio[25722]: info: Spotify config file written Jan 27 17:02:09 volumio volumio[25722]: 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 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio sudo[25960]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:02:09 volumio sudo[25960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:09 volumio volumio[25722]: info: No need to fix Spotify hosts Jan 27 17:02:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:10 volumio go-librespot[25982]: go-librespot daemon starting... Jan 27 17:02:10 volumio sudo[25960]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=debug msg="app state loaded" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=info msg="zeroconf server listening on port 42865" Jan 27 17:02:10 volumio volumio[25722]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:02:10 volumio volumio[25722]: SPOTIFY: BQCne0aYPpe7YuhNVKxTtfY0IvkqzXMMQ3gUdFHK4D9v619zephyNup8SqQ7lKdyX6DedhjbR7uj4CY1_m2_xeyGIdaznkFaxJZvyYn5_d-09xryx1LIE8e16j9A7E6G7ItVgqkFDnJrx5q754ph62dTu-_t7KRtzxSRJeZAZOy4IQzep8LVUDoU6fc3pNxvMkWFV7DavT1D2GXbMd0zXiKSLsAnG2_mgoEJXplJPwL9eyrpwst5HuQhCJugfwejvKsyHLjTZAGiUMe2-iyB2LFKG20DTd8y2-sqzvBQ2t9buQIn_MIy9kvB Jan 27 17:02:10 volumio volumio[25722]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:02:10 volumio volumio[25722]: info: New Spotify access token = BQCne0aYPpe7YuhNVKxTtfY0IvkqzXMMQ3gUdFHK4D9v619zephyNup8SqQ7lKdyX6DedhjbR7uj4CY1_m2_xeyGIdaznkFaxJZvyYn5_d-09xryx1LIE8e16j9A7E6G7ItVgqkFDnJrx5q754ph62dTu-_t7KRtzxSRJeZAZOy4IQzep8LVUDoU6fc3pNxvMkWFV7DavT1D2GXbMd0zXiKSLsAnG2_mgoEJXplJPwL9eyrpwst5HuQhCJugfwejvKsyHLjTZAGiUMe2-iyB2LFKG20DTd8y2-sqzvBQ2t9buQIn_MIy9kvB Jan 27 17:02:10 volumio volumio[25722]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 17:02:10 volumio go-librespot[25986]: time="2026-01-27T17:02:10+07:00" level=debug msg="obtained new client token: AACcjwrlsOd+rkgW+9Qz/NexPIC+IBpzYR3Ab1UZxiR2PI9rvrJbXqUKj23crLEWmDIHrOUkVgAfTbVEePr56rYqHQRjiP8m7+q5bpoIYwod5IL+O61Ec5JfGivFrGeVF2yFYLw6DY0ubSn6ef+tGF6u3SUH+AtVzs1O4KhbfqI/w/M3Qk7jkZZV1hDS9Hgw0uELx+5V18PZM4H+EXlKBKsKvOApzLWPjlvsJL1A5yWgRLq+hWVDvbhKdsg=" Jan 27 17:02:10 volumio volumio[25722]: info: Starting Shairport Sync Jan 27 17:02:11 volumio volumio[25722]: info: Starting Shairport Sync Jan 27 17:02:11 volumio volumio[25722]: info: Starting Shairport Sync Jan 27 17:02:11 volumio go-librespot[25986]: time="2026-01-27T17:02:11+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:11 volumio sudo[25997]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:11 volumio sudo[25997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:11 volumio sudo[25995]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:11 volumio sudo[25995]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:11 volumio sudo[25999]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:11 volumio sudo[25999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:11 volumio go-librespot[25986]: time="2026-01-27T17:02:11+07:00" level=debug msg="completed keyexchange" Jan 27 17:02:11 volumio go-librespot[25986]: time="2026-01-27T17:02:11+07:00" level=debug msg="completed challenge" Jan 27 17:02:11 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:02:11 volumio go-librespot[25986]: time="2026-01-27T17:02:11+07: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 27 17:02:11 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:02:11 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:11 volumio systemd[1]: shairport-sync.service: Consumed 2.624s CPU time. Jan 27 17:02:11 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:11 volumio sudo[25997]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:11 volumio sudo[25999]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:11 volumio sudo[25995]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:11 volumio volumio[25722]: info: Shairport-Sync Started Jan 27 17:02:11 volumio volumio[25722]: Error adding Membership: Error: addMembership EINVAL Jan 27 17:02:11 volumio volumio[25722]: info: Shairport-Sync Started Jan 27 17:02:11 volumio volumio[25722]: info: Shairport-Sync Started Jan 27 17:02:11 volumio volumio[25722]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:11 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:11 volumio volumio[25722]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 27 17:02:11 volumio volumio[25722]: info: Spotify Successfully logged in Jan 27 17:02:11 volumio volumio[25722]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:11 volumio volumio[25722]: info: [1769508131871] CoreMusicLibrary::Adding element Spotify Jan 27 17:02:11 volumio volumio[25722]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:11 volumio volumio[25722]: Cannot find translation for source YouTube Music Jan 27 17:02:11 volumio volumio[25722]: Cannot find translation for source Spotify Jan 27 17:02:12 volumio volumio[25722]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 17:02:12 volumio volumio[25722]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:12 volumio volumio[25722]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:12 volumio volumio[25722]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:12 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:12 volumio volumio[25722]: info: CoreStateMachine::pushState Jan 27 17:02:12 volumio volumio[25722]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:12 volumio volumio[25722]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:13 volumio volumio[25722]: info: go-librespot daemon successfully initialized Jan 27 17:02:13 volumio mpd[25945]: 2026-01-27T17:02:13 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 17:02:13 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 17:02:13 volumio sudo[25915]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:13 volumio sudo[25898]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:14 volumio volumio[25722]: error: MPD error: The expression evaluated to a falsy value: Jan 27 17:02:14 volumio volumio[25722]: assert.ok(self.idling) Jan 27 17:02:14 volumio volumio[25722]: error: The expression evaluated to a falsy value: Jan 27 17:02:14 volumio volumio[25722]: assert.ok(self.idling) Jan 27 17:02:14 volumio volumio[25722]: info: MPD running with PID25945 Jan 27 17:02:14 volumio volumio[25722]: ,establishing connection Jan 27 17:02:14 volumio volumio[25722]: error: MPD error: The expression evaluated to a falsy value: Jan 27 17:02:14 volumio volumio[25722]: assert.ok(self.idling) Jan 27 17:02:14 volumio volumio[25722]: error: The expression evaluated to a falsy value: Jan 27 17:02:14 volumio volumio[25722]: assert.ok(self.idling) Jan 27 17:02:14 volumio volumio[25722]: info: Completed starting Core Plugins Jan 27 17:02:14 volumio volumio[25722]: info: ------------------------------------------- Jan 27 17:02:14 volumio volumio[25722]: info: ----- MyVolumio plugins startup ---- Jan 27 17:02:14 volumio volumio[25722]: info: ------------------------------------------- Jan 27 17:02:14 volumio volumio[25722]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 17:02:14 volumio volumio[25722]: error: updateQueue error: null Jan 27 17:02:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jan 27 17:02:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:14 volumio go-librespot[26038]: go-librespot daemon starting... Jan 27 17:02:14 volumio go-librespot[26039]: time="2026-01-27T17:02:14+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:14 volumio go-librespot[26039]: time="2026-01-27T17:02:14+07:00" level=debug msg="app state loaded" Jan 27 17:02:14 volumio go-librespot[26039]: time="2026-01-27T17:02:14+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=info msg="zeroconf server listening on port 41757" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=debug msg="obtained new client token: AACVne7WwYg/OxW1DHJCn99DlnZefqtyl+/it14ZoYPqWvykiZZCURWSNa/h0+yTY2rYxK2L5PlEsc3I4FAb95H3mNqde/Z445SVvO6FRbyCUPp6vzEyvtHHsyn+iW14QhbhwY4GdgokA33T8YrscLPDHbicfTvUMT0EcNpSBKQbriqXGzRADLirnyJDeRpmUYilsXhAYJHD0PDWOxMOkZ9ZdTgAqNp06pyXpKV9enMEQM4UJBee20cL2mE=" Jan 27 17:02:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:15 volumio go-librespot[26039]: time="2026-01-27T17:02:15+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:16 volumio volumio[25722]: info: Initializing connection to go-librespot Websocket Jan 27 17:02:16 volumio volumio[25722]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:02:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Jan 27 17:02:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:18 volumio go-librespot[26046]: go-librespot daemon starting... Jan 27 17:02:18 volumio go-librespot[26047]: time="2026-01-27T17:02:18+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:18 volumio go-librespot[26047]: time="2026-01-27T17:02:18+07:00" level=debug msg="app state loaded" Jan 27 17:02:18 volumio go-librespot[26047]: time="2026-01-27T17:02:18+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:19 volumio volumio[25722]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=info msg="zeroconf server listening on port 41125" Jan 27 17:02:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="obtained new client token: AACwAwgwfdU4i+0+pNL1hYlYI3FdVPSCOC+kk4fF0VfHjaQ57SkhlN3P9LIS/RCQTdq8gVljZRt6cf9q5j73/m2NW+wwY46i0JcbVE83AUiA+9RQjmg27u4hBCSb/5tDoM+ezDPUif0nq0FU+s60S+uEDdk26Wzszk/q2ZBAb7hI/RtSD3QhfFxMG1POxf2pZOr8vCRseUPzvInM2oU3cfDmO3fl0wVijCZtfK4Pi9ueYGmc3jTIPq+M5xU=" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="completed keyexchange" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="completed challenge" Jan 27 17:02:19 volumio volumio[25722]: info: Initializing connection to go-librespot Websocket Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07:00" level=debug msg="new websocket client" Jan 27 17:02:19 volumio go-librespot[26047]: time="2026-01-27T17:02:19+07: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 27 17:02:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:19 volumio volumio[25722]: info: Connection to go-librespot Websocket established Jan 27 17:02:19 volumio volumio[25722]: info: Connection to go-librespot Websocket closed Jan 27 17:02:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Jan 27 17:02:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:22 volumio volumio[25722]: info: Getting Spotify volume Jan 27 17:02:23 volumio volumio[25722]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:02:23 volumio volumio[25722]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:02:23 volumio volumio[25722]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 27 17:02:23 volumio volumio[25722]: errno: -111, Jan 27 17:02:23 volumio volumio[25722]: code: 'ECONNREFUSED', Jan 27 17:02:23 volumio volumio[25722]: syscall: 'connect', Jan 27 17:02:23 volumio volumio[25722]: address: '127.0.0.1', Jan 27 17:02:23 volumio volumio[25722]: port: 9879, Jan 27 17:02:23 volumio volumio[25722]: response: undefined Jan 27 17:02:23 volumio volumio[25722]: } Jan 27 17:02:23 volumio volumio[25722]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:02:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:23 volumio go-librespot[26054]: go-librespot daemon starting... Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=debug msg="app state loaded" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=info msg="zeroconf server listening on port 34707" Jan 27 17:02:23 volumio go-librespot[26057]: time="2026-01-27T17:02:23+07:00" level=debug msg="obtained new client token: AAD+C+AWUbs/hNochnTcgfCZAh+5x/I1PlKvkUqk6feu5rI4UVoGdlTzSMUTn680Zf9FJwJ2SJzNk+Td7YJKHZ29pE4aiLWlpaushxR8128vSFt3t6jXXbrY2y3fvJVXFvslX9rqF28aCvVREEKGCLG3eRosARfiJuigVMosryxwqhChQoRNBFBn0lbEGZKWvSczw2wgtCRngViUoqGUjOlVptNgjxkqjE0ZCVjaUrBLzTGXrBUYIz4VnMc=" Jan 27 17:02:24 volumio go-librespot[26057]: time="2026-01-27T17:02:24+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:24 volumio go-librespot[26057]: time="2026-01-27T17:02:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:24 volumio sudo[26090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 17:01' Jan 27 17:02:24 volumio sudo[26090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:24 volumio sudo[26090]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:25 volumio volumio-remote-updater[628]: [2026-01-27 17:02:25] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 27 17:02:25 volumio volumio-remote-updater[628]: [2026-01-27 17:02:25] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 27 17:02:25 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:25 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 17:02:25 volumio systemd[1]: volumio.service: Consumed 1min 234ms CPU time. Jan 27 17:02:25 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 17:02:25 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 17:02:25 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8865. Jan 27 17:02:25 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 17:02:25 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 17:02:25 volumio systemd[1]: volumio.service: Consumed 1min 234ms CPU time. Jan 27 17:02:25 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 17:02:25 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 17:02:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Jan 27 17:02:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:27 volumio go-librespot[26117]: go-librespot daemon starting... Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=debug msg="app state loaded" Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:27 volumio go-librespot[26118]: time="2026-01-27T17:02:27+07:00" level=info msg="zeroconf server listening on port 43167" Jan 27 17:02:28 volumio go-librespot[26118]: time="2026-01-27T17:02:28+07:00" level=debug msg="obtained new client token: AAD1//Os8h2wHNqU0I826ENkbzt1d+ytlNSgpoUDDOUlfP75etOqWkRatBI3eMAhj01twFSrioL3G1/HYnu2qL4rPxVpzeTnJUaBbohWTXIeC4g/eJ9AQcyTPsGDfulQ+ku6V5VGYqQtaWIDsVJt0ZA8FuKiScQxEI2TU5RcVIGtKJJaa/rHew1xF5DIUWURYP13bfLadtj6PaUvnEWtg1qB7A93T0ja0eZh7FLQY6c61oNe+y63Yo2c" Jan 27 17:02:28 volumio go-librespot[26118]: time="2026-01-27T17:02:28+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:28 volumio go-librespot[26118]: time="2026-01-27T17:02:28+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.107:45312->104.199.241.202:4070: read: connection reset by peer" Jan 27 17:02:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:28 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:28 volumio volumio[26102]: info: ----- Volumio3 ---- Jan 27 17:02:28 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:28 volumio volumio[26102]: info: ----- System startup ---- Jan 27 17:02:28 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:30 volumio volumio-remote-updater[628]: [2026-01-27 17:02:30] [connect] Successful connection Jan 27 17:02:30 volumio volumio[26102]: info: MYVOLUMIO Environment detected Jan 27 17:02:30 volumio volumio[26102]: info: Plugin folders cleanup Jan 27 17:02:30 volumio volumio[26102]: info: Scanning into folder /volumio/app/plugins/ Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category audio_interface Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category miscellanea Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category music_service Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category plugins.json Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category system_controller Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category user_interface Jan 27 17:02:30 volumio volumio[26102]: info: Scanning into folder /data/plugins/ Jan 27 17:02:30 volumio volumio[26102]: info: Scanning category music_service Jan 27 17:02:30 volumio volumio[26102]: info: Plugin folders cleanup completed Jan 27 17:02:30 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:30 volumio volumio[26102]: info: ----- Core plugins startup ---- Jan 27 17:02:30 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:30 volumio volumio[26102]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 17:02:30 volumio volumio[26102]: info: Adding plugin upnp to MyMusic Plugins Jan 27 17:02:30 volumio volumio[26102]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 17:02:30 volumio volumio[26102]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 17:02:30 volumio volumio[26102]: info: Loading plugins from folder /data/plugins/ Jan 27 17:02:30 volumio volumio[26102]: info: Loading plugin "system"... Jan 27 17:02:30 volumio volumio[26102]: info: Loading plugin "appearance"... Jan 27 17:02:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Jan 27 17:02:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:31 volumio go-librespot[26138]: go-librespot daemon starting... Jan 27 17:02:31 volumio go-librespot[26139]: time="2026-01-27T17:02:31+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:31 volumio go-librespot[26139]: time="2026-01-27T17:02:31+07:00" level=debug msg="app state loaded" Jan 27 17:02:31 volumio go-librespot[26139]: time="2026-01-27T17:02:31+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=info msg="zeroconf server listening on port 44551" Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=debug msg="obtained new client token: AADtyZhlnwVC5Mjrfxbd/KlslzM3lo4KEpR64YpUXTUF6r287oeoHqT7U7MeMpqUYxzHmTWBo1URZ8t4fLuZjMf0UN7iidj59GXDgD1f95QB/UQE5PWcxAvXgIrTsvixds16G3IJJDinIGhR4Srgqq5W0P6HDydE9HPzc5C2ilys8rs568o/vvKjjRHlESVnGUuG3sht4NplAFVf1t2tuou8aauCXMPhQcK39y4wcWgJVP0iL7TH/aCZYYI=" Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "network"... Jan 27 17:02:32 volumio volumio[26102]: info: Refreshing Cached IP Addresses Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:32 volumio sudo[26147]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:02:32 volumio sudo[26147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:32 volumio sudo[26149]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "services"... Jan 27 17:02:32 volumio sudo[26147]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:32 volumio sudo[26149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "alsa_controller"... Jan 27 17:02:32 volumio go-librespot[26139]: time="2026-01-27T17:02:32+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:32 volumio sudo[26149]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:32 volumio sudo[26160]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 17:02:32 volumio sudo[26160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:32 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "wizard"... Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "networkfs"... Jan 27 17:02:32 volumio volumio[26102]: info: Starting Udev Watcher for removable devices Jan 27 17:02:32 volumio volumio[26102]: info: Ignoring mount for partition: boot Jan 27 17:02:32 volumio volumio[26102]: info: Ignoring mount for partition: volumio Jan 27 17:02:32 volumio volumio[26102]: info: Ignoring mount for partition: volumio_data Jan 27 17:02:32 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "volumio_command_line_client"... Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "upnp"... Jan 27 17:02:32 volumio volumio[26102]: info: [1769508152878] Starting Upmpd Daemon Jan 27 17:02:32 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "my_music"... Jan 27 17:02:32 volumio volumio[26102]: info: Loading plugin "mpd"... Jan 27 17:02:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:33 volumio volumio[26102]: info: Loading plugin "upnp_browser"... Jan 27 17:02:35 volumio sudo[26160]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Jan 27 17:02:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:35 volumio go-librespot[26180]: go-librespot daemon starting... Jan 27 17:02:35 volumio go-librespot[26181]: time="2026-01-27T17:02:35+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:35 volumio go-librespot[26181]: time="2026-01-27T17:02:35+07:00" level=debug msg="app state loaded" Jan 27 17:02:35 volumio go-librespot[26181]: time="2026-01-27T17:02:35+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=info msg="zeroconf server listening on port 42211" Jan 27 17:02:36 volumio volumio[26102]: info: Starting UPNP Browser Jan 27 17:02:36 volumio volumio[26102]: info: Loading plugin "alarm-clock"... Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="obtained new client token: AABgawfSAButJD9D+sKjp9tDYvYYbXSH4sDebNp18hXne+v2FQ/CKQZGvl1lEJJH0h2Sig7gmC+qS3F3OxneTOEj29aJkjlHwJeOhddjxdETcQcIlGHMli4uI5ChlcJQxbRAZrcSQO11siMgyXwhOjdZQWkYuXX8tg4pm8/hcSsicyEF5aDe6Jsioh6nEWoETun3u1NFt98E4921SoxAfuN9OqdrmX4O9DoJHvL/sMhgTFaLibMkUBAX2Sg=" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:36 volumio volumio[26102]: info: Loading plugin "airplay_emulation"... Jan 27 17:02:36 volumio volumio[26102]: info: Starting Shairport Sync Jan 27 17:02:36 volumio volumio[26102]: info: Loading plugin "last_100"... Jan 27 17:02:36 volumio volumio[26102]: info: Loading plugin "webradio"... Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="completed keyexchange" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07:00" level=debug msg="completed challenge" Jan 27 17:02:36 volumio go-librespot[26181]: time="2026-01-27T17:02:36+07: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 27 17:02:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:37 volumio volumio[26102]: info: Loading plugin "i2s_dacs"... Jan 27 17:02:37 volumio volumio[26102]: info: Loading plugin "volumiodiscovery"... Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** For more information see Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:02:37 volumio volumio[26102]: *** WARNING *** For more information see Jan 27 17:02:37 volumio node[26102]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 17:02:37 volumio node[26102]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:02:37 volumio node[26102]: *** WARNING *** For more information see Jan 27 17:02:37 volumio node[26102]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 17:02:37 volumio node[26102]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:02:37 volumio node[26102]: *** WARNING *** For more information see Jan 27 17:02:37 volumio volumio[26102]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 17:02:37 volumio volumio[26102]: info: Discovery: Started advertising with name: Volumio Jan 27 17:02:37 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:02:37 volumio volumio[26102]: info: Loading plugin "spop"... Jan 27 17:02:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:39 volumio volumio[26102]: info: Loading plugin "ytcr"... Jan 27 17:02:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Jan 27 17:02:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:40 volumio go-librespot[26190]: go-librespot daemon starting... Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=debug msg="app state loaded" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:40 volumio go-librespot[26191]: time="2026-01-27T17:02:40+07:00" level=info msg="zeroconf server listening on port 46205" Jan 27 17:02:41 volumio go-librespot[26191]: time="2026-01-27T17:02:41+07:00" level=debug msg="obtained new client token: AAAlza6cVHl1DckqS3pU5XKqTGx67oH6mJFUAxFh+6nWcPzPLC5nMhcuwlZarHY785GLq4FgQC6mOu4JoZpph2igVCOdWhq5R/hNKKpapVhnjefytsl+RtkhcDWJHEe3wP9IfTlwA8jsOffjM4+wflAxgQzH/J5/xUwmrUdpK8FMfN7SjLITcO4FsulD0VUvsgxNVMTmuNWdyQgOAHS4TN1zyQ7fWtBMZ7fHotN0rrKo7oiW4r4vCbvj" Jan 27 17:02:41 volumio go-librespot[26191]: time="2026-01-27T17:02:41+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:41 volumio go-librespot[26191]: time="2026-01-27T17:02:41+07:00" level=debug msg="completed keyexchange" Jan 27 17:02:41 volumio go-librespot[26191]: time="2026-01-27T17:02:41+07:00" level=debug msg="completed challenge" Jan 27 17:02:41 volumio go-librespot[26191]: time="2026-01-27T17:02:41+07: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 27 17:02:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:41 volumio volumio[26102]: info: Loading plugin "ytmusic"... Jan 27 17:02:42 volumio volumio-remote-updater[628]: [2026-01-27 17:02:42] [connect] Successful connection Jan 27 17:02:42 volumio volumio[26102]: info: Loading plugin "outputs"... Jan 27 17:02:42 volumio volumio[26102]: info: Loading plugin "albumart"... Jan 27 17:02:42 volumio volumio[26102]: info: Plugin example_plugin is not enabled Jan 27 17:02:42 volumio volumio[26102]: info: Loading plugin "inputs"... Jan 27 17:02:42 volumio volumio[26102]: info: Loading plugin "updater_comm"... Jan 27 17:02:43 volumio volumio[26102]: info: Plugin mpdemulation is not enabled Jan 27 17:02:43 volumio volumio[26102]: info: Loading plugin "rest_api"... Jan 27 17:02:43 volumio volumio[26102]: info: Loading plugin "websocket"... Jan 27 17:02:43 volumio volumio[26102]: info: Starting Socket.io Server version 1.7.4 Jan 27 17:02:43 volumio volumio[26102]: info: Loading plugin "RoonBridge"... Jan 27 17:02:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:43 volumio volumio[26102]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 17:02:43 volumio volumio[26102]: info: Loading i18n strings for locale en Jan 27 17:02:43 volumio volumio[26102]: Updating browse sources language Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::initPlayerControls Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:43 volumio volumio[26102]: Express server listening on port 3000 Jan 27 17:02:43 volumio volumio[26102]: [Metrics] WebUI: 15s 980.18ms Jan 27 17:02:43 volumio volumio[26214]: Forking 3 albumart workers Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::resetVolumioState Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::getcurrentVolume Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:44 volumio sudo[26240]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:02:44 volumio sudo[26240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:44 volumio sudo[26240]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:44 volumio sudo[26258]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:02:44 volumio sudo[26258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:44 volumio sudo[26258]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:44 volumio volumio[26102]: info: Volumio Network Manager: Network status updated: 1 Jan 27 17:02:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Jan 27 17:02:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:44 volumio go-librespot[26266]: go-librespot daemon starting... Jan 27 17:02:44 volumio volumio-remote-updater[628]: [2026-01-27 17:02:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769508162 101 Jan 27 17:02:44 volumio go-librespot[26267]: time="2026-01-27T17:02:44+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:44 volumio go-librespot[26267]: time="2026-01-27T17:02:44+07:00" level=debug msg="app state loaded" Jan 27 17:02:44 volumio go-librespot[26267]: time="2026-01-27T17:02:44+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:44 volumio volumio[26102]: 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 27 17:02:44 volumio volumio[26102]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::pushState Jan 27 17:02:44 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::updateTrackBlock Jan 27 17:02:44 volumio volumio[26102]: info: CorePlayQueue::getTrackBlock Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:44 volumio volumio[26102]: info: Reloading queue from file Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::setRepeat null single undefined Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::pushState Jan 27 17:02:44 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::setRandom null Jan 27 17:02:44 volumio volumio[26102]: info: CoreStateMachine::pushState Jan 27 17:02:44 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:44 volumio volumio[26102]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:44 volumio volumio[26102]: info: Setting Device type: Raspberry PI Jan 27 17:02:45 volumio volumio[26102]: info: Completed loading Core Plugins Jan 27 17:02:45 volumio volumio[26102]: info: Preparing to generate the ALSA configuration file Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=info msg="zeroconf server listening on port 45083" Jan 27 17:02:45 volumio volumio[26102]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:45 volumio volumio[26102]: info: CoreStateMachine::pushState Jan 27 17:02:45 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:45 volumio volumio[26102]: info: Asound.conf file unchanged, so no further update is needed Jan 27 17:02:45 volumio volumio[26102]: info: Output device has changed, restarting MPD Jan 27 17:02:45 volumio sudo[26284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 17:02:45 volumio sudo[26284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:45 volumio volumio[26102]: info: Output device has changed, restarting Shairport Sync Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:45 volumio sudo[26286]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:02:45 volumio sudo[26286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=debug msg="obtained new client token: AABTWpbUDSZIKXtG74q5K7P0IOXu61ncFgdDcWwNO4hVHMdWAI2XQVPXKoL/xPNpD/LWSDKKosXwmlgPsrhbtAYcMSflHzc+F+53XmQlZ6xPmh5H++fTWxWHRqj9X886wM/Eqk3i8D1cCvuzFczBfjdv3WlFY2jdZMrIMbHjHUe+r4MxG3ocJ9SqzUiws1xNNAKOrHaAYVHP6zAmF3DquP7wy4qvrnImYuQpsMwOhaWidSmIBpyyVK6Wr3k=" Jan 27 17:02:45 volumio sudo[26286]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:45 volumio sudo[26289]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:02:45 volumio sudo[26289]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:45 volumio sudo[26284]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:45 volumio volumio[26102]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:45 volumio volumio[26102]: info: ___________ START PLUGINS ___________ Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:45 volumio volumio[26102]: info: ControllerMpd::onStart: Initializing MPD Jan 27 17:02:45 volumio volumio[26102]: info: Creating MPD Configuration file Jan 27 17:02:45 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 17:02:45 volumio go-librespot[26267]: time="2026-01-27T17:02:45+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:45 volumio volumio[26102]: info: [1769508165785] CoreMusicLibrary::Adding element Media Servers Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:45 volumio volumio[26102]: info: UPNP Browser: Client initialized successfully Jan 27 17:02:45 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:02:45 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:02:45 volumio systemd[1]: mpd.service: Consumed 7.159s CPU time. Jan 27 17:02:45 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:02:45 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:02:45 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:45 volumio sudo[26299]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:45 volumio sudo[26299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:45 volumio sudo[26297]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:02:45 volumio sudo[26297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:45 volumio sudo[26297]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:45 volumio volumio[26102]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:45 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:45 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:02:45 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:02:46 volumio volumio[26102]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:46 volumio volumio[26102]: info: [1769508166039] CoreMusicLibrary::Adding element Last_100 Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:46 volumio volumio[26102]: info: [1769508166055] CoreMusicLibrary::Adding element Webradio Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:46 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:02:46 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:02:46 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:02:46 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:02:46 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:02:46 volumio volumio[26102]: info: Initializing BBC Radios Jan 27 17:02:46 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:02:46 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:46 volumio volumio[26102]: info: Creating Spotify config file Jan 27 17:02:46 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:46 volumio sudo[26322]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 17:02:46 volumio sudo[26322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 17:02:46 volumio sudo[26322]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:47 volumio volumio[26230]: Starting albumart workers Jan 27 17:02:47 volumio volumio[26229]: Starting albumart workers Jan 27 17:02:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:47 volumio volumio[26227]: Starting albumart workers Jan 27 17:02:47 volumio volumio[26102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:47 volumio volumio[26102]: info: [1769508167729] CoreMusicLibrary::Adding element YouTube Music Jan 27 17:02:47 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:47 volumio volumio[26102]: Cannot find translation for source YouTube Music Jan 27 17:02:47 volumio volumio[26102]: info: Volumio Calling Home Jan 27 17:02:47 volumio sudo[26333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 17:02:47 volumio sudo[26333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:48 volumio sudo[26333]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:48 volumio volumio[26102]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:02:48 volumio volumio[26102]: info: Discovery: Found device Volumio Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:48 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:48 volumio volumio[26102]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:02:48 volumio volumio[26102]: info: Discovery: Found device Volumio Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:48 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:48 volumio volumio[26102]: info: MPD Permissions set Jan 27 17:02:48 volumio volumio[26102]: info: MPD Permissions set Jan 27 17:02:48 volumio volumio[26102]: info: Upmpdcli Daemon Started Jan 27 17:02:48 volumio volumio[26102]: info: Volumio called home Jan 27 17:02:48 volumio volumio[26102]: info: Spotify config file written Jan 27 17:02:48 volumio sudo[26339]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:02:48 volumio volumio[26102]: 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 27 17:02:48 volumio sudo[26339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:48 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:49 volumio go-librespot[26347]: go-librespot daemon starting... Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:02:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:02:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:49 volumio sudo[26339]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:49 volumio go-librespot[26357]: go-librespot daemon starting... Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:02:49 volumio volumio[26102]: info: No need to fix Spotify hosts Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=debug msg="app state loaded" Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:49 volumio go-librespot[26361]: time="2026-01-27T17:02:49+07:00" level=info msg="zeroconf server listening on port 36989" Jan 27 17:02:50 volumio go-librespot[26361]: time="2026-01-27T17:02:50+07:00" level=debug msg="obtained new client token: AADxMz8A/Nw9oFti+nVh6qEWsFTO/NUQAFPZMKIOm/WcHG7941M5Wka7iyZRrFbCi/45fzoRX9dnU1/MAbzco2dsyO18i0+QMVoCfRZGjvJNJ57UYhNfNyLtew0Rjueec3gHqkRvNzHg4RABhtwtybkcljOiwTxzQduHeBhuyfYyGZ+zMOm7wpNS6++q4imcHMmDmVziFVZZ4RAf/DIE9lDH95mb8v+n0KdYaGo2chWJc4au8UXZpIhg" Jan 27 17:02:50 volumio go-librespot[26361]: time="2026-01-27T17:02:50+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:50 volumio go-librespot[26361]: time="2026-01-27T17:02:50+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:50 volumio volumio[26102]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:02:50 volumio volumio[26102]: SPOTIFY: BQDy3CYlcMig-Xzv4bdNteM2FiWUvugIZS9aIbO-ApW6F01UEZ7s7x2ZyWCF_hkcHAeySUNMNFJm04-_Jq1XMxjXoEjFb75FYlTKA27YoA6rYpTQwVRMERahrPFIAoZmy-h1GZUhBYmp4IlFyeReolBklMDcmmKoIoBPJV6peUaiucjJUC6Cj3heZ-bYX3QSmo7A6uANEksFPuEopYVkk9gXlyeNcaZrOnfxm1HIBMVcA1X8lJmN0ZNXZ4XXDU4XtGa8rR5eH9Fl6nou3WxYdTTZ7Xejv0UJhuoD0J_Qk2vBVBTCbz6DH6IH Jan 27 17:02:50 volumio volumio[26102]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:02:50 volumio volumio[26102]: info: New Spotify access token = BQDy3CYlcMig-Xzv4bdNteM2FiWUvugIZS9aIbO-ApW6F01UEZ7s7x2ZyWCF_hkcHAeySUNMNFJm04-_Jq1XMxjXoEjFb75FYlTKA27YoA6rYpTQwVRMERahrPFIAoZmy-h1GZUhBYmp4IlFyeReolBklMDcmmKoIoBPJV6peUaiucjJUC6Cj3heZ-bYX3QSmo7A6uANEksFPuEopYVkk9gXlyeNcaZrOnfxm1HIBMVcA1X8lJmN0ZNXZ4XXDU4XtGa8rR5eH9Fl6nou3WxYdTTZ7Xejv0UJhuoD0J_Qk2vBVBTCbz6DH6IH Jan 27 17:02:50 volumio volumio[26102]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 17:02:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:50 volumio volumio[26102]: info: Starting Shairport Sync Jan 27 17:02:50 volumio volumio[26102]: info: Starting Shairport Sync Jan 27 17:02:50 volumio volumio[26102]: info: Starting Shairport Sync Jan 27 17:02:50 volumio sudo[26384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:50 volumio sudo[26384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:50 volumio sudo[26388]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:50 volumio sudo[26388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:50 volumio sudo[26386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:02:50 volumio sudo[26386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:02:50 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:02:50 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:02:50 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:50 volumio systemd[1]: shairport-sync.service: Consumed 2.291s CPU time. Jan 27 17:02:50 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:50 volumio sudo[26384]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:50 volumio sudo[26388]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:51 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:02:51 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:02:51 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:51 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:02:51 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:51 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:51 volumio sudo[26386]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:51 volumio volumio[26102]: info: Shairport-Sync Started Jan 27 17:02:51 volumio volumio[26102]: Error adding Membership: Error: addMembership EINVAL Jan 27 17:02:51 volumio volumio[26102]: info: Shairport-Sync Started Jan 27 17:02:51 volumio volumio[26102]: info: Shairport-Sync Started Jan 27 17:02:51 volumio volumio[26102]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 27 17:02:51 volumio volumio[26102]: info: Spotify Successfully logged in Jan 27 17:02:51 volumio volumio[26102]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:02:51 volumio volumio[26102]: info: [1769508171395] CoreMusicLibrary::Adding element Spotify Jan 27 17:02:51 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:02:51 volumio volumio[26102]: Cannot find translation for source YouTube Music Jan 27 17:02:51 volumio volumio[26102]: Cannot find translation for source Spotify Jan 27 17:02:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:52 volumio volumio[26102]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 17:02:52 volumio volumio[26102]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:02:52 volumio volumio[26102]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:02:52 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:02:52 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:52 volumio volumio[26102]: info: CoreStateMachine::pushState Jan 27 17:02:52 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:02:52 volumio volumio[26102]: info: CoreCommandRouter::volumioPushState Jan 27 17:02:53 volumio volumio[26102]: info: go-librespot daemon successfully initialized Jan 27 17:02:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 17:02:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:53 volumio go-librespot[26425]: go-librespot daemon starting... Jan 27 17:02:53 volumio go-librespot[26426]: time="2026-01-27T17:02:53+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:53 volumio go-librespot[26426]: time="2026-01-27T17:02:53+07:00" level=debug msg="app state loaded" Jan 27 17:02:53 volumio go-librespot[26426]: time="2026-01-27T17:02:53+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:53 volumio mpd[26330]: 2026-01-27T17:02:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 17:02:53 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 17:02:53 volumio sudo[26289]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:53 volumio sudo[26299]: pam_unix(sudo:session): session closed for user root Jan 27 17:02:54 volumio volumio[26102]: error: MPD error: The expression evaluated to a falsy value: Jan 27 17:02:54 volumio volumio[26102]: assert.ok(self.idling) Jan 27 17:02:54 volumio volumio[26102]: error: The expression evaluated to a falsy value: Jan 27 17:02:54 volumio volumio[26102]: assert.ok(self.idling) Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=info msg="zeroconf server listening on port 34829" Jan 27 17:02:54 volumio volumio[26102]: info: Completed starting Core Plugins Jan 27 17:02:54 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:54 volumio volumio[26102]: info: ----- MyVolumio plugins startup ---- Jan 27 17:02:54 volumio volumio[26102]: info: ------------------------------------------- Jan 27 17:02:54 volumio volumio[26102]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 17:02:54 volumio volumio[26102]: info: MPD running with PID26330 Jan 27 17:02:54 volumio volumio[26102]: ,establishing connection Jan 27 17:02:54 volumio volumio[26102]: error: updateQueue error: null Jan 27 17:02:54 volumio volumio[26102]: error: updateQueue error: null Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=debug msg="obtained new client token: AAA5A7Om3rWF0usoTrQSVtnFKPEDAGVar/ZY+MBeAI1AEw5g06LtaXU/gblpi4v5nmPC/cxFmjmVXxfRFmomSDWIEH45nn1NXSQg1kifZNHkjZAZtWn2s+4UXleY16Y/JK+7Ay74jTMnvi0ciUoZsSX7Jgc9oxIkrZULYfH3GSlAge1RhQNnpfOaa/PiMR3MCxr0I6LykBZQ/TPWAVRjiVq/WhLq9ykwUR05EHOClDHfXtIQMGOvAQm3Ing=" Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:54 volumio go-librespot[26426]: time="2026-01-27T17:02:54+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:56 volumio volumio[26102]: info: Initializing connection to go-librespot Websocket Jan 27 17:02:56 volumio volumio[26102]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:02:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:02:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 17:02:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:02:57 volumio go-librespot[26438]: go-librespot daemon starting... Jan 27 17:02:57 volumio go-librespot[26439]: time="2026-01-27T17:02:57+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:02:57 volumio go-librespot[26439]: time="2026-01-27T17:02:57+07:00" level=debug msg="app state loaded" Jan 27 17:02:57 volumio go-librespot[26439]: time="2026-01-27T17:02:57+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=info msg="zeroconf server listening on port 41299" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=debug msg="obtained new client token: AACVM7niU+5vQ+i6xKqm03rVuPNY9XvbM/+9fhoR6pVXVLMwnkS4fgnlKkqPlakkT1YMtei+9zYT31BdTmoLKDagKM/N3JReQ7qL3wfGQVFi0Sm/cmZNk6G1YlTzl7DcYZ4bU4QgrU1ng6QDIsTEGPaMXmhPhURWqXB3Z/5pUwgMVJ6B0ThB/N5xui0JiBHhxt6gCo2B4iAjeYgDXHG+7g4ygLqRIeU21vd94J6eLoYD5941+9NCSXWgZaU=" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:02:58 volumio go-librespot[26439]: time="2026-01-27T17:02:58+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:02:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:02:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:02:59 volumio volumio[26102]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 17:02:59 volumio volumio[26102]: info: Initializing connection to go-librespot Websocket Jan 27 17:02:59 volumio volumio[26102]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:02:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:02:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:02:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 17:03:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:02 volumio go-librespot[26447]: go-librespot daemon starting... Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="app state loaded" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:02 volumio volumio[26102]: info: Initializing connection to go-librespot Websocket Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="new websocket client" Jan 27 17:03:02 volumio volumio[26102]: info: Connection to go-librespot Websocket established Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=info msg="zeroconf server listening on port 44611" Jan 27 17:03:02 volumio go-librespot[26448]: time="2026-01-27T17:03:02+07:00" level=debug msg="obtained new client token: AACgTBdkOTJNXLaNDtFOnS+xfd7k6IbGePiOSvABw+f0tPRcFKaUUKXAdYIPUISsQbR+/ZfZd+aqz2RkMjbEGwPhF9YdE2c6rD/rU6z3vXMa8Hcm+zBN+4QWMGlzYDtEIGvc9jKHo4D5mp0SAyPypsd4kkbmwSH8cTSdLtfOTqVwhJkbL6CQa12A3AQMiGPmpRiNUU4mpgjTTj9B+zEiCfXuPGC8Hicb8GyMQP99ixOiL/Wh+sQB1VSEe6Q=" Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 17:03:02 volumio volumio[26102]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 17:03:03 volumio volumio[26102]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 17:03:03 volumio go-librespot[26448]: time="2026-01-27T17:03:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:03 volumio go-librespot[26448]: time="2026-01-27T17:03:03+07:00" level=debug msg="completed keyexchange" Jan 27 17:03:03 volumio go-librespot[26448]: time="2026-01-27T17:03:03+07:00" level=debug msg="completed challenge" Jan 27 17:03:03 volumio go-librespot[26448]: time="2026-01-27T17:03:03+07: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 27 17:03:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:04 volumio volumio[26102]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 17:03:04 volumio volumio[26102]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 17:03:04 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:04 volumio volumio[26102]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:04 volumio volumio[26102]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 17:03:04 volumio volumio[26102]: info: MyVolumio login type: Token Jan 27 17:03:04 volumio volumio[26102]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 17:03:04 volumio volumio[26102]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 17:03:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:06 volumio volumio[26102]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 17:03:06 volumio volumio[26102]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 17:03:06 volumio volumio[26102]: info: Streaming services startup Jan 27 17:03:06 volumio volumio[26102]: info: Starting Streaming Daemon Jan 27 17:03:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 17:03:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:06 volumio sudo[26472]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 17:03:06 volumio volumio[26102]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 17:03:06 volumio sudo[26472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:06 volumio go-librespot[26471]: go-librespot daemon starting... Jan 27 17:03:06 volumio sudo[26472]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:06 volumio go-librespot[26478]: time="2026-01-27T17:03:06+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:06 volumio go-librespot[26478]: time="2026-01-27T17:03:06+07:00" level=debug msg="app state loaded" Jan 27 17:03:06 volumio go-librespot[26478]: time="2026-01-27T17:03:06+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:06 volumio volumio[26102]: info: Getting Spotify volume Jan 27 17:03:06 volumio volumio[26102]: info: Connection to go-librespot Websocket closed Jan 27 17:03:06 volumio volumio[26102]: error: Cannot start Volumio Streaming Daemon Jan 27 17:03:06 volumio volumio[26102]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 17:03:06 volumio volumio[26102]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 17:03:06 volumio volumio[26102]: 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 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=info msg="zeroconf server listening on port 41733" Jan 27 17:03:07 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:07 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=debug msg="obtained new client token: AACF76u7GKYK0Z4ljaJOiRVXBpYGlhSa8JwHCLhn/O5Fi2v9+zqB993+oejnu9YWBYXtMJKZYh2Vy2TJdq29c3AAVxrc4OzaqhvqpPhffdUV3U32khEDAloF+PaTuEI5uIRnhT3WrlOiYYamCVIdD8+5HdITKVWgyS1jMNjcmzDLJsHwdW1m4ChVnodK6efDHhBE934SkS4iWccqyG7nbHyGoSlic/9zSIC4C/67qSJE6DaKGg1iKw4Y+iQ=" Jan 27 17:03:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:07 volumio volumio[26102]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 17:03:07 volumio volumio[26102]: SPOTIFY: SPOTIFY VOLUME undefined Jan 27 17:03:07 volumio volumio[26102]: SPOTIFY: VOLUMIO VOLUME 100 Jan 27 17:03:07 volumio volumio[26102]: info: Aligning Spotify Volume to Volumio Volume Jan 27 17:03:07 volumio volumio[26102]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:07 volumio volumio[26102]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:07 volumio volumio[26102]: info: Setting Spotify Volume from Volumio: 100 Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:07 volumio go-librespot[26478]: time="2026-01-27T17:03:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:07 volumio volumio[26102]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:03:07 volumio volumio[26102]: Error: socket hang up Jan 27 17:03:07 volumio volumio[26102]: at connResetException (node:internal/errors:720:14) Jan 27 17:03:07 volumio volumio[26102]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 27 17:03:07 volumio volumio[26102]: at Socket.emit (node:events:526:35) Jan 27 17:03:07 volumio volumio[26102]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 27 17:03:07 volumio volumio[26102]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 27 17:03:07 volumio volumio[26102]: code: 'ECONNRESET', Jan 27 17:03:07 volumio volumio[26102]: response: undefined Jan 27 17:03:07 volumio volumio[26102]: } Jan 27 17:03:07 volumio volumio[26102]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:03:09 volumio sudo[26499]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 17:02' Jan 27 17:03:09 volumio sudo[26499]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:09 volumio sudo[26499]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 27 17:03:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:11 volumio go-librespot[26507]: go-librespot daemon starting... Jan 27 17:03:11 volumio volumio-remote-updater[628]: [2026-01-27 17:03:11] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Jan 27 17:03:11 volumio volumio-remote-updater[628]: [2026-01-27 17:03:11] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="app state loaded" Jan 27 17:03:11 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:11 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 17:03:11 volumio systemd[1]: volumio.service: Consumed 1min 8.616s CPU time. Jan 27 17:03:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 17:03:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 17:03:11 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8866. Jan 27 17:03:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 17:03:11 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 17:03:11 volumio systemd[1]: volumio.service: Consumed 1min 8.616s CPU time. Jan 27 17:03:11 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 17:03:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 17:03:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=info msg="zeroconf server listening on port 42605" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="obtained new client token: AADGoFiYzPExvEfcPVejfE3ykyrqV5Hl9v1ZW6Rg5OXuc4QACpHcqLQtvOgSk81Zt+1P1sJaggEnqfuprhRb6kDJkIoETeQ3kPkVEK7sYDw6WEW/9Bib/z6zZTPbHsR5avEp/x/OFzjJ5VLyWC6dMOOrtNvOyqLfVE4f05sEfKQbBJipyUOE0SIm1FTZTQoMHluXVnKtkeynXkvSyTk1frRn1d4zh4Rhx5xPlum7cpbOexP1z7WRPwsiiLY=" Jan 27 17:03:11 volumio go-librespot[26508]: time="2026-01-27T17:03:11+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:12 volumio go-librespot[26508]: time="2026-01-27T17:03:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:14 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:14 volumio volumio[26523]: info: ----- Volumio3 ---- Jan 27 17:03:14 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:14 volumio volumio[26523]: info: ----- System startup ---- Jan 27 17:03:14 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 27 17:03:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:15 volumio go-librespot[26546]: go-librespot daemon starting... Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=debug msg="app state loaded" Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:15 volumio go-librespot[26547]: time="2026-01-27T17:03:15+07:00" level=info msg="zeroconf server listening on port 45715" Jan 27 17:03:16 volumio volumio-remote-updater[628]: [2026-01-27 17:03:16] [connect] Successful connection Jan 27 17:03:16 volumio go-librespot[26547]: time="2026-01-27T17:03:16+07:00" level=debug msg="obtained new client token: AADIB2Yvz793ouFR8Zwkks7jt1FFy3gBN+YOA0spqLKF+VFbhcWxEhli+TUqXlfbAC9PKJb4fg1LGCip8sYTsH4z6FD0ycGOsGbJ4Ct2aYXVjjH6QQ5VWSLUPO9mVGVNPq9pYMDO2R21g3DMH0Dp9esydHts7BdOY6TKUWHZ4hP/zuSPHDjZKpgugMHcRa2lKGQKIsH8gceYVYX3Ku/b4QaCwmaOma+TLjwA3b7FAxnrQU7RigMC5PbR" Jan 27 17:03:16 volumio go-librespot[26547]: time="2026-01-27T17:03:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:16 volumio go-librespot[26547]: time="2026-01-27T17:03:16+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:16 volumio volumio[26523]: info: MYVOLUMIO Environment detected Jan 27 17:03:16 volumio volumio[26523]: info: Plugin folders cleanup Jan 27 17:03:16 volumio volumio[26523]: info: Scanning into folder /volumio/app/plugins/ Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category audio_interface Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category miscellanea Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category music_service Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category plugins.json Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category system_controller Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category user_interface Jan 27 17:03:16 volumio volumio[26523]: info: Scanning into folder /data/plugins/ Jan 27 17:03:16 volumio volumio[26523]: info: Scanning category music_service Jan 27 17:03:16 volumio volumio[26523]: info: Plugin folders cleanup completed Jan 27 17:03:16 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:16 volumio volumio[26523]: info: ----- Core plugins startup ---- Jan 27 17:03:16 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:16 volumio volumio[26523]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 17:03:16 volumio volumio[26523]: info: Adding plugin upnp to MyMusic Plugins Jan 27 17:03:16 volumio volumio[26523]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 17:03:16 volumio volumio[26523]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 17:03:16 volumio volumio[26523]: info: Loading plugins from folder /data/plugins/ Jan 27 17:03:16 volumio volumio[26523]: info: Loading plugin "system"... Jan 27 17:03:16 volumio volumio[26523]: info: Loading plugin "appearance"... Jan 27 17:03:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:18 volumio volumio[26523]: info: Loading plugin "network"... Jan 27 17:03:18 volumio volumio[26523]: info: Refreshing Cached IP Addresses Jan 27 17:03:18 volumio sudo[26562]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:03:18 volumio sudo[26562]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:18 volumio sudo[26564]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:03:18 volumio sudo[26564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:18 volumio sudo[26562]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:18 volumio volumio[26523]: info: Loading plugin "services"... Jan 27 17:03:18 volumio volumio[26523]: info: Loading plugin "alsa_controller"... Jan 27 17:03:18 volumio sudo[26564]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:18 volumio sudo[26572]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 17:03:18 volumio sudo[26572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:18 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:03:18 volumio volumio[26523]: info: Loading plugin "wizard"... Jan 27 17:03:18 volumio volumio[26523]: info: Loading plugin "networkfs"... Jan 27 17:03:18 volumio volumio[26523]: info: Starting Udev Watcher for removable devices Jan 27 17:03:18 volumio volumio[26523]: info: Ignoring mount for partition: boot Jan 27 17:03:18 volumio volumio[26523]: info: Ignoring mount for partition: volumio Jan 27 17:03:18 volumio volumio[26523]: info: Ignoring mount for partition: volumio_data Jan 27 17:03:18 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:03:19 volumio volumio[26523]: info: Loading plugin "volumio_command_line_client"... Jan 27 17:03:19 volumio volumio[26523]: info: Loading plugin "upnp"... Jan 27 17:03:19 volumio volumio[26523]: info: [1769508199022] Starting Upmpd Daemon Jan 27 17:03:19 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:03:19 volumio volumio[26523]: info: Loading plugin "my_music"... Jan 27 17:03:19 volumio volumio[26523]: info: Loading plugin "mpd"... Jan 27 17:03:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 27 17:03:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:19 volumio go-librespot[26595]: go-librespot daemon starting... Jan 27 17:03:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:19 volumio go-librespot[26596]: time="2026-01-27T17:03:19+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:19 volumio go-librespot[26596]: time="2026-01-27T17:03:19+07:00" level=debug msg="app state loaded" Jan 27 17:03:19 volumio go-librespot[26596]: time="2026-01-27T17:03:19+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:19 volumio volumio[26523]: info: Loading plugin "upnp_browser"... Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=info msg="zeroconf server listening on port 41601" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=debug msg="obtained new client token: AAD2Jrb9rUxmFXPDP1cTuNmPLQ/hpg2RpUZ0bicDpXdw86c4Z7ybP6oq3CMQ8sevAsyZkgwm9weJbvJv4amUURsU4DdgaS7d4hevIiLAZcdunSX7DQhjIuxmyQsJhPdPLn+KN1bTbZpFK1mtnXal3qFbKXSmavfOnvb0FHWglpdEjLuhDOOBO4afA0M1+y1K4ReoLvI12ypME5/BfXOrxWq9nFmmMhwRAoL1DbMz0rYAVUzfrwM03yUjiFg=" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:20 volumio go-librespot[26596]: time="2026-01-27T17:03:20+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:21 volumio sudo[26572]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:22 volumio volumio[26523]: info: Starting UPNP Browser Jan 27 17:03:22 volumio volumio[26523]: info: Loading plugin "alarm-clock"... Jan 27 17:03:22 volumio volumio[26523]: info: Loading plugin "airplay_emulation"... Jan 27 17:03:22 volumio volumio[26523]: info: Starting Shairport Sync Jan 27 17:03:22 volumio volumio[26523]: info: Loading plugin "last_100"... Jan 27 17:03:22 volumio volumio[26523]: info: Loading plugin "webradio"... Jan 27 17:03:23 volumio volumio[26523]: info: Loading plugin "i2s_dacs"... Jan 27 17:03:23 volumio volumio[26523]: info: Loading plugin "volumiodiscovery"... Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** For more information see Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:03:23 volumio volumio[26523]: *** WARNING *** For more information see Jan 27 17:03:23 volumio node[26523]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 17:03:23 volumio node[26523]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:03:23 volumio node[26523]: *** WARNING *** For more information see Jan 27 17:03:23 volumio node[26523]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 17:03:23 volumio node[26523]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 17:03:23 volumio node[26523]: *** WARNING *** For more information see Jan 27 17:03:23 volumio volumio[26523]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 17:03:23 volumio volumio[26523]: info: Discovery: Started advertising with name: Volumio Jan 27 17:03:23 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 17:03:23 volumio volumio[26523]: info: Loading plugin "spop"... Jan 27 17:03:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 27 17:03:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:23 volumio go-librespot[26605]: go-librespot daemon starting... Jan 27 17:03:23 volumio go-librespot[26606]: time="2026-01-27T17:03:23+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:23 volumio go-librespot[26606]: time="2026-01-27T17:03:23+07:00" level=debug msg="app state loaded" Jan 27 17:03:23 volumio go-librespot[26606]: time="2026-01-27T17:03:23+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=info msg="zeroconf server listening on port 34971" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=debug msg="obtained new client token: AACZUbh7xDMDjvC8u+aMd+PQxnC1a34K/A1+Au/RvI/FOxmtVXcFgmCrHXm6mq9xUIN+zpej065lfrQvfdKuHyo4gY9GmaZHwQDpx54CWJpeRzbIWnqyq2G7WiBm3yJngiF9uwZ9Vsh2jzxZPtyd8WvYQwxAZc+mbdiEH+cy5fSqg/GtiKIgpxblUYpt80hRYNjO1lKT/DJjOvpFqK4OMxQVO6WTExEblNWRgCYiqaYIAURxrRykCd4lMls=" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:24 volumio go-librespot[26606]: time="2026-01-27T17:03:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:25 volumio volumio[26523]: info: Loading plugin "ytcr"... Jan 27 17:03:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:27 volumio volumio[26523]: info: Loading plugin "ytmusic"... Jan 27 17:03:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 27 17:03:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:28 volumio go-librespot[26614]: go-librespot daemon starting... Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="app state loaded" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:28 volumio volumio-remote-updater[628]: [2026-01-27 17:03:28] [connect] Successful connection Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=info msg="zeroconf server listening on port 41895" Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="obtained new client token: AAD9ubix+eGaFKvIMdmGsZwvrzz6OLAIg47hQkbnVmgebNjMbCpgo3Qlvhff9h5QqdyTZCIU4yTO2xekuYjEdlonklT3lQE3JQ/OBHE6VmsH00GM2pkaGhRkliVEE67uFgBeoZhFAw6iEq8LNoXAUvdkkQho71giuEGyM8iiwtFbD0Y+9lFfFwZNSP4DJk8pilKsTcrLgwVE++dNpyDOLqrLLi4IsajAVJM2s1RSIXqtelixVgy270w8Q0M=" Jan 27 17:03:28 volumio volumio[26523]: info: Loading plugin "outputs"... Jan 27 17:03:28 volumio volumio[26523]: info: Loading plugin "albumart"... Jan 27 17:03:28 volumio volumio[26523]: info: Plugin example_plugin is not enabled Jan 27 17:03:28 volumio volumio[26523]: info: Loading plugin "inputs"... Jan 27 17:03:28 volumio volumio[26523]: info: Loading plugin "updater_comm"... Jan 27 17:03:28 volumio go-librespot[26615]: time="2026-01-27T17:03:28+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:29 volumio go-librespot[26615]: time="2026-01-27T17:03:29+07:00" level=debug msg="completed keyexchange" Jan 27 17:03:29 volumio go-librespot[26615]: time="2026-01-27T17:03:29+07:00" level=debug msg="completed challenge" Jan 27 17:03:29 volumio volumio[26523]: info: Plugin mpdemulation is not enabled Jan 27 17:03:29 volumio volumio[26523]: info: Loading plugin "rest_api"... Jan 27 17:03:29 volumio go-librespot[26615]: time="2026-01-27T17:03:29+07: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 27 17:03:29 volumio volumio[26523]: info: Loading plugin "websocket"... Jan 27 17:03:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:29 volumio volumio[26523]: info: Starting Socket.io Server version 1.7.4 Jan 27 17:03:29 volumio volumio[26523]: info: Loading plugin "RoonBridge"... Jan 27 17:03:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:29 volumio volumio[26523]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 17:03:29 volumio volumio[26523]: info: Loading i18n strings for locale en Jan 27 17:03:29 volumio volumio[26523]: Updating browse sources language Jan 27 17:03:29 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:30 volumio volumio[26636]: Forking 3 albumart workers Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::initPlayerControls Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: Express server listening on port 3000 Jan 27 17:03:30 volumio volumio[26523]: [Metrics] WebUI: 16s 45.31ms Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::resetVolumioState Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::getcurrentVolume Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:03:30 volumio sudo[26678]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 17:03:30 volumio sudo[26678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:30 volumio sudo[26678]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:30 volumio sudo[26680]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 17:03:30 volumio sudo[26680]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:30 volumio sudo[26680]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:30 volumio volumio[26523]: info: Volumio Network Manager: Network status updated: 1 Jan 27 17:03:30 volumio volumio[26523]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::pushState Jan 27 17:03:30 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::volumioPushState Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::updateTrackBlock Jan 27 17:03:30 volumio volumio[26523]: info: CorePlayQueue::getTrackBlock Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:03:30 volumio volumio-remote-updater[628]: [2026-01-27 17:03:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769508208 101 Jan 27 17:03:30 volumio volumio[26523]: 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 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:30 volumio volumio[26523]: info: Reloading queue from file Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::setRepeat null single undefined Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::pushState Jan 27 17:03:30 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::volumioPushState Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::setRandom null Jan 27 17:03:30 volumio volumio[26523]: info: CoreStateMachine::pushState Jan 27 17:03:30 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:30 volumio volumio[26523]: info: CoreCommandRouter::volumioPushState Jan 27 17:03:30 volumio volumio[26523]: info: Setting Device type: Raspberry PI Jan 27 17:03:31 volumio volumio[26523]: info: Completed loading Core Plugins Jan 27 17:03:31 volumio volumio[26523]: info: Preparing to generate the ALSA configuration file Jan 27 17:03:31 volumio volumio[26523]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:03:31 volumio volumio[26523]: info: CoreStateMachine::pushState Jan 27 17:03:31 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::volumioPushState Jan 27 17:03:31 volumio volumio[26523]: info: Asound.conf file unchanged, so no further update is needed Jan 27 17:03:31 volumio volumio[26523]: info: Output device has changed, restarting MPD Jan 27 17:03:31 volumio volumio[26523]: info: Output device has changed, restarting Shairport Sync Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:31 volumio sudo[26696]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 17:03:31 volumio sudo[26696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:31 volumio sudo[26698]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:03:31 volumio sudo[26698]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:31 volumio sudo[26698]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:31 volumio sudo[26700]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:03:31 volumio sudo[26700]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:31 volumio volumio[26523]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:03:31 volumio volumio[26523]: info: ___________ START PLUGINS ___________ Jan 27 17:03:31 volumio volumio[26523]: info: ControllerMpd::onStart: Initializing MPD Jan 27 17:03:31 volumio volumio[26523]: info: Creating MPD Configuration file Jan 27 17:03:31 volumio sudo[26696]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:31 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 17:03:31 volumio sudo[26709]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:03:31 volumio sudo[26709]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:31 volumio sudo[26709]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:31 volumio volumio[26523]: info: [1769508211568] CoreMusicLibrary::Adding element Media Servers Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:31 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:03:31 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:03:31 volumio systemd[1]: mpd.service: Consumed 7.359s CPU time. Jan 27 17:03:31 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:03:31 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:03:31 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:03:31 volumio sudo[26711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 17:03:31 volumio sudo[26711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:31 volumio volumio[26523]: info: UPNP Browser: Client initialized successfully Jan 27 17:03:31 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:03:31 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:03:31 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 17:03:31 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:31 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 17:03:31 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 17:03:31 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 17:03:31 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 17:03:31 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 17:03:31 volumio volumio[26523]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:31 volumio volumio[26523]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 17:03:31 volumio volumio[26523]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:03:32 volumio volumio[26523]: info: [1769508212002] CoreMusicLibrary::Adding element Last_100 Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:03:32 volumio volumio[26523]: info: [1769508212024] CoreMusicLibrary::Adding element Webradio Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:03:32 volumio volumio[26523]: info: Initializing BBC Radios Jan 27 17:03:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 27 17:03:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:32 volumio go-librespot[26737]: go-librespot daemon starting... Jan 27 17:03:32 volumio sudo[26722]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 17:03:32 volumio sudo[26722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 17:03:32 volumio sudo[26722]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:32 volumio volumio[26523]: info: Creating Spotify config file Jan 27 17:03:32 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:32 volumio go-librespot[26741]: time="2026-01-27T17:03:32+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:33 volumio go-librespot[26741]: time="2026-01-27T17:03:33+07:00" level=info msg="zeroconf server listening on port 35089" Jan 27 17:03:33 volumio volumio[26647]: Starting albumart workers Jan 27 17:03:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:33 volumio volumio[26646]: Starting albumart workers Jan 27 17:03:33 volumio volumio[26523]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:03:33 volumio volumio[26523]: info: [1769508213705] CoreMusicLibrary::Adding element YouTube Music Jan 27 17:03:33 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:33 volumio volumio[26523]: Cannot find translation for source YouTube Music Jan 27 17:03:33 volumio volumio[26648]: Starting albumart workers Jan 27 17:03:33 volumio volumio[26523]: info: Volumio Calling Home Jan 27 17:03:33 volumio sudo[26752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 17:03:33 volumio sudo[26752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:34 volumio sudo[26752]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:34 volumio volumio[26523]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:03:34 volumio volumio[26523]: info: Discovery: Found device Volumio Jan 27 17:03:34 volumio volumio[26523]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:34 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:34 volumio volumio[26523]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 17:03:34 volumio volumio[26523]: info: Discovery: Found device Volumio Jan 27 17:03:34 volumio volumio[26523]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:34 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:34 volumio volumio[26523]: info: MPD Permissions set Jan 27 17:03:34 volumio volumio[26523]: info: MPD Permissions set Jan 27 17:03:34 volumio volumio[26523]: info: Upmpdcli Daemon Started Jan 27 17:03:34 volumio volumio[26523]: info: Volumio called home Jan 27 17:03:34 volumio volumio[26523]: info: Spotify config file written Jan 27 17:03:35 volumio sudo[26760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 17:03:35 volumio sudo[26760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:35 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 17:03:35 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 17:03:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:35 volumio go-librespot[26768]: go-librespot daemon starting... Jan 27 17:03:35 volumio sudo[26760]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:35 volumio go-librespot[26769]: time="2026-01-27T17:03:35+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:35 volumio go-librespot[26769]: time="2026-01-27T17:03:35+07:00" level=debug msg="app state loaded" Jan 27 17:03:35 volumio go-librespot[26769]: time="2026-01-27T17:03:35+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:35 volumio volumio[26523]: 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 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 17:03:35 volumio volumio[26523]: info: No need to fix Spotify hosts Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=info msg="zeroconf server listening on port 39035" Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=debug msg="obtained new client token: AAASiYCzOeNjKjU86tbTk2arsbm3FfVvLi5P/ZFuZf1FyURV/LruP2UYgBf1v3b5DeBe7kRMJdwGm1GJE3TpDbLVLNgSzogtOkqxk3I+MuUomYGkhSBRm+gvSa20WAt+GLnGHEeB5we5u6oFi6/yJ2pe/VLFiIeA4ni+ztQ/oI17edSScw0TTsDqoNYFz9IwPsXgO/6tbninAyBGGsVR7Ial+zt4WRGY2zEwhb16J4lS+pTpUqFSPkutCsQ=" Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:36 volumio volumio[26523]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:03:36 volumio volumio[26523]: SPOTIFY: BQAr7ygy2ihQxhFv9r661hFOOSgncbKqh_R1OPIKaoKJoQEUWUGWDKt4UwPXTLgb1ZxnmmOWn477W0QWScohGCMgiHNs-i5oV3zibt_KVqEcnFWOTWWtnPiKib2tnJ0w9wyh_qNaDSmSRV1H8rOVurDkmKjeBUxcxgdl57wBPiVkweWuelRONeZwbVrLj-WMooZGuwjJ_IQOvCkZUsnDY7oMDl8xQ8tGrb6EVM7tRFpgcep1rIzHjMIxZC6E8g4p0ttxwkJS3Kv78Bkmd2ASqnOx5sRCml3j92DUj2P1hjyocQ7vVcx-i8fp Jan 27 17:03:36 volumio volumio[26523]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 17:03:36 volumio go-librespot[26769]: time="2026-01-27T17:03:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:36 volumio volumio[26523]: info: New Spotify access token = BQAr7ygy2ihQxhFv9r661hFOOSgncbKqh_R1OPIKaoKJoQEUWUGWDKt4UwPXTLgb1ZxnmmOWn477W0QWScohGCMgiHNs-i5oV3zibt_KVqEcnFWOTWWtnPiKib2tnJ0w9wyh_qNaDSmSRV1H8rOVurDkmKjeBUxcxgdl57wBPiVkweWuelRONeZwbVrLj-WMooZGuwjJ_IQOvCkZUsnDY7oMDl8xQ8tGrb6EVM7tRFpgcep1rIzHjMIxZC6E8g4p0ttxwkJS3Kv78Bkmd2ASqnOx5sRCml3j92DUj2P1hjyocQ7vVcx-i8fp Jan 27 17:03:36 volumio volumio[26523]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 17:03:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:36 volumio volumio[26523]: info: Starting Shairport Sync Jan 27 17:03:36 volumio volumio[26523]: info: Starting Shairport Sync Jan 27 17:03:36 volumio volumio[26523]: info: Starting Shairport Sync Jan 27 17:03:36 volumio sudo[26800]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:03:36 volumio sudo[26800]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:36 volumio sudo[26802]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:03:36 volumio sudo[26802]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:36 volumio sudo[26804]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 17:03:36 volumio sudo[26804]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:36 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 17:03:36 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 17:03:36 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:03:36 volumio systemd[1]: shairport-sync.service: Consumed 2.469s CPU time. Jan 27 17:03:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 17:03:37 volumio sudo[26804]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:37 volumio sudo[26800]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:37 volumio sudo[26802]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:37 volumio volumio[26523]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:37 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:37 volumio volumio[26523]: info: Shairport-Sync Started Jan 27 17:03:37 volumio volumio[26523]: Error adding Membership: Error: addMembership EINVAL Jan 27 17:03:37 volumio volumio[26523]: info: Shairport-Sync Started Jan 27 17:03:37 volumio volumio[26523]: info: Shairport-Sync Started Jan 27 17:03:37 volumio volumio[26523]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 27 17:03:37 volumio volumio[26523]: info: Spotify Successfully logged in Jan 27 17:03:37 volumio volumio[26523]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 17:03:37 volumio volumio[26523]: info: [1769508217436] CoreMusicLibrary::Adding element Spotify Jan 27 17:03:37 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 17:03:37 volumio volumio[26523]: Cannot find translation for source YouTube Music Jan 27 17:03:37 volumio volumio[26523]: Cannot find translation for source Spotify Jan 27 17:03:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:37 volumio volumio[26523]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 17:03:37 volumio volumio[26523]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 17:03:38 volumio volumio[26523]: info: VolumeController:: Volume=100 Mute =false Jan 27 17:03:38 volumio volumio[26523]: info: CoreCommandRouter::volumioGetState Jan 27 17:03:38 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:38 volumio volumio[26523]: info: CoreStateMachine::pushState Jan 27 17:03:38 volumio volumio[26523]: info: CorePlayQueue::getTrack 0 Jan 27 17:03:38 volumio volumio[26523]: info: CoreCommandRouter::volumioPushState Jan 27 17:03:39 volumio volumio[26523]: info: go-librespot daemon successfully initialized Jan 27 17:03:39 volumio mpd[26748]: 2026-01-27T17:03:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 17:03:39 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 17:03:39 volumio sudo[26711]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:39 volumio sudo[26700]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 17:03:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:39 volumio go-librespot[26844]: go-librespot daemon starting... Jan 27 17:03:39 volumio volumio[26523]: error: MPD error: The expression evaluated to a falsy value: Jan 27 17:03:39 volumio volumio[26523]: assert.ok(self.idling) Jan 27 17:03:39 volumio volumio[26523]: error: The expression evaluated to a falsy value: Jan 27 17:03:39 volumio volumio[26523]: assert.ok(self.idling) Jan 27 17:03:39 volumio volumio[26523]: info: MPD running with PID26748 Jan 27 17:03:39 volumio volumio[26523]: ,establishing connection Jan 27 17:03:39 volumio volumio[26523]: error: updateQueue error: null Jan 27 17:03:39 volumio go-librespot[26845]: time="2026-01-27T17:03:39+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:39 volumio go-librespot[26845]: time="2026-01-27T17:03:39+07:00" level=debug msg="app state loaded" Jan 27 17:03:39 volumio go-librespot[26845]: time="2026-01-27T17:03:39+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:39 volumio volumio[26523]: info: Completed starting Core Plugins Jan 27 17:03:39 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:39 volumio volumio[26523]: info: ----- MyVolumio plugins startup ---- Jan 27 17:03:39 volumio volumio[26523]: info: ------------------------------------------- Jan 27 17:03:39 volumio volumio[26523]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 17:03:39 volumio volumio[26523]: error: updateQueue error: null Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=info msg="zeroconf server listening on port 39295" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=debug msg="obtained new client token: AACUsmajIBvmfpfiR/+LVTy9pgnK50YO1TNnH4fokISyQiAn9Xfrh4mxu5zbbKfzCK2BJ5iPpfO78Cu0WhX+kmyt9LbhRHPnzDwWh8Cqkz/+SSso7D8/V0gPBwdbdzQ3l0t3Zq0ZFf5KSyq1nHGO/HJM2wFLXQrO/4E6do4RkC1cLvggFJSu4j/aDFvMEMN0wqT9TEbhQNWDpQzy5ASqFWUDmEV0oNDnEKIx9jIvLk91ragH7NHbQzS5850=" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:40 volumio go-librespot[26845]: time="2026-01-27T17:03:40+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 17:03:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:42 volumio volumio[26523]: info: Initializing connection to go-librespot Websocket Jan 27 17:03:42 volumio volumio[26523]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:03:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 17:03:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:44 volumio go-librespot[26852]: go-librespot daemon starting... Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=debug msg="app state loaded" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:44 volumio volumio[26523]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=info msg="zeroconf server listening on port 40401" Jan 27 17:03:44 volumio go-librespot[26853]: time="2026-01-27T17:03:44+07:00" level=debug msg="obtained new client token: AAAAUCcXJOb9LTcjlSi68NTLEAdRez9vLx17+1T6BHg9nIle2GBNkfK5VWCddfsWHjax6ESNfZk6jPkCc+KDiRhDJeAsOMqPQF2UMlHAoPy95hXVCT4XJ4/divHBhMAnvDLFChyQKUmvJLk7eSFCfeODQeFK3k6hjNNuoM96/yysBhaDJU6MuI8BbDqb+XITha5u/ALx7ymMmHNmizYzvQrCdnPx7eIwVdwVmXPg1eYc/Os1dLI2L7irDHw=" Jan 27 17:03:45 volumio go-librespot[26853]: time="2026-01-27T17:03:45+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:45 volumio go-librespot[26853]: time="2026-01-27T17:03:45+07:00" level=debug msg="completed keyexchange" Jan 27 17:03:45 volumio go-librespot[26853]: time="2026-01-27T17:03:45+07:00" level=debug msg="completed challenge" Jan 27 17:03:45 volumio go-librespot[26853]: time="2026-01-27T17:03:45+07: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 27 17:03:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:45 volumio volumio[26523]: info: Initializing connection to go-librespot Websocket Jan 27 17:03:45 volumio volumio[26523]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:03:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 17:03:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:48 volumio go-librespot[26860]: go-librespot daemon starting... Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=debug msg="app state loaded" Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:48 volumio volumio[26523]: info: Initializing connection to go-librespot Websocket Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=debug msg="new websocket client" Jan 27 17:03:48 volumio volumio[26523]: info: Connection to go-librespot Websocket established Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 17:03:48 volumio volumio[26523]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:48 volumio go-librespot[26861]: time="2026-01-27T17:03:48+07:00" level=info msg="zeroconf server listening on port 42363" Jan 27 17:03:49 volumio go-librespot[26861]: time="2026-01-27T17:03:49+07:00" level=debug msg="obtained new client token: AAB2PmskxFPC0T9Eag7G+MrHqVVSgu1WW5k/oUW/G4W91vrbtVH2owQ4BXo6otHwnFV/IJQhyDocmtfr1oWhrsYO7U0j8fBrr0p0Km4mpJyHGOWSBQTSPX6OhgWXtfWXb/b0umEyeMzU1AhrcsanFT6VaqtIiaaPARzb6CeVUfJW8cr9rpsIlS1BI1iKq0ujTtBJc+1xktOmSlI/R/iXf9+eYTkcIs2yR8VK3JlC3wqbou5DGL2l5GVg" Jan 27 17:03:49 volumio go-librespot[26861]: time="2026-01-27T17:03:49+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 17:03:49 volumio go-librespot[26861]: time="2026-01-27T17:03:49+07:00" level=debug msg="completed keyexchange" Jan 27 17:03:49 volumio go-librespot[26861]: time="2026-01-27T17:03:49+07:00" level=debug msg="completed challenge" Jan 27 17:03:49 volumio go-librespot[26861]: time="2026-01-27T17:03:49+07: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 27 17:03:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:50 volumio volumio[26523]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 17:03:50 volumio volumio[26523]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 17:03:50 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:50 volumio volumio[26523]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 17:03:50 volumio volumio[26523]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 17:03:50 volumio volumio[26523]: info: MyVolumio login type: Token Jan 27 17:03:50 volumio volumio[26523]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 17:03:50 volumio volumio[26523]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 17:03:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:52 volumio volumio[26523]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 17:03:52 volumio volumio[26523]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 17:03:52 volumio volumio[26523]: info: Streaming services startup Jan 27 17:03:52 volumio volumio[26523]: info: Starting Streaming Daemon Jan 27 17:03:52 volumio sudo[26884]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 17:03:52 volumio volumio[26523]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 17:03:52 volumio sudo[26884]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 17:03:52 volumio sudo[26884]: pam_unix(sudo:session): session closed for user root Jan 27 17:03:52 volumio volumio[26523]: info: Getting Spotify volume Jan 27 17:03:52 volumio volumio[26523]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:03:52 volumio volumio[26523]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 17:03:52 volumio volumio[26523]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 27 17:03:52 volumio volumio[26523]: errno: -111, Jan 27 17:03:52 volumio volumio[26523]: code: 'ECONNREFUSED', Jan 27 17:03:52 volumio volumio[26523]: syscall: 'connect', Jan 27 17:03:52 volumio volumio[26523]: address: '127.0.0.1', Jan 27 17:03:52 volumio volumio[26523]: port: 9879, Jan 27 17:03:52 volumio volumio[26523]: response: undefined Jan 27 17:03:52 volumio volumio[26523]: } Jan 27 17:03:52 volumio volumio[26523]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 17:03:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 17:03:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 17:03:52 volumio go-librespot[26901]: go-librespot daemon starting... Jan 27 17:03:52 volumio go-librespot[26902]: time="2026-01-27T17:03:52+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 17:03:52 volumio go-librespot[26902]: time="2026-01-27T17:03:52+07:00" level=debug msg="app state loaded" Jan 27 17:03:52 volumio go-librespot[26902]: time="2026-01-27T17:03:52+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=info msg="zeroconf server listening on port 37919" Jan 27 17:03:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 17:03:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 17:03:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="obtained new client token: AABQjHRZBLiQPF9Ks5ZVZURMsZXRSi6upBTPCGjvZDsSKMRSy5OcL7/YbcYmZ3QnlnXXKxmGNXxmK9dtnSNyms2Aqwzk0i9T/Sva/SzK54+oGvI/FqHo84hKoGTx/BFDv30AIoWU9REBXFdN1sWEG9zHYQFJ4ZlVP4dI1+JwpSl3YjULjclEpfgT8iX31dGnyV6WkJ9XQ2oMGA41TxJPFuMrDoYN/ALQW1SpkclHc3P80prs7mpNEN9sGTo=" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="completed keyexchange" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07:00" level=debug msg="completed challenge" Jan 27 17:03:53 volumio go-librespot[26902]: time="2026-01-27T17:03:53+07: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 27 17:03:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 17:03:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 17:03:54 volumio sudo[26913]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 17:02' Jan 27 17:03:54 volumio sudo[26913]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"