Jan 27 22:21:00 volumio volumio[27099]: info: go-librespot daemon successfully initialized Jan 27 22:21:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 22:21:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:01 volumio go-librespot[27416]: go-librespot daemon starting... Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+07:00" level=debug msg="app state loaded" Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:01 volumio mpd[27318]: 2026-01-27T22:21:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 22:21:01 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 22:21:01 volumio sudo[27289]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:01 volumio sudo[27278]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:01 volumio volumio[27099]: error: MPD error: The expression evaluated to a falsy value: Jan 27 22:21:01 volumio volumio[27099]: assert.ok(self.idling) Jan 27 22:21:01 volumio volumio[27099]: error: The expression evaluated to a falsy value: Jan 27 22:21:01 volumio volumio[27099]: assert.ok(self.idling) Jan 27 22:21:01 volumio volumio[27099]: error: updateQueue error: null Jan 27 22:21:01 volumio volumio[27099]: info: MPD running with PID27318 Jan 27 22:21:01 volumio volumio[27099]: ,establishing connection Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+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 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+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 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+07:00" level=info msg="zeroconf server listening on port 35791" Jan 27 22:21:01 volumio volumio[27099]: info: Completed starting Core Plugins Jan 27 22:21:01 volumio volumio[27099]: info: ------------------------------------------- Jan 27 22:21:01 volumio volumio[27099]: info: ----- MyVolumio plugins startup ---- Jan 27 22:21:01 volumio volumio[27099]: info: ------------------------------------------- Jan 27 22:21:01 volumio volumio[27099]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 22:21:01 volumio volumio[27099]: error: updateQueue error: null Jan 27 22:21:01 volumio go-librespot[27417]: time="2026-01-27T22:21:01+07:00" level=debug msg="obtained new client token: AAC42jtVNfOdl0IzEx8+38G7XL/XM1L9Vn4V+Uzx+I/x89lAsGtSksMk53FWz2HuunsBbjBD54+2FLS3N4z+dlOqhSq09mTJqVBZs1i4M4mEXxYDOEssnkpJvwqVqyTZlzkm8T8MUgstzRwdqw6Z4Gz6cWo1V8wCPEW4Nggpe34pNa8RlKxIRE3LaNJJLZsCKK6o0e05mLoKZSvXY3udGFD0Ecx/olDQnQNiJTAIRJ8GX1XtXfh9heyQpE8=" Jan 27 22:21:02 volumio go-librespot[27417]: time="2026-01-27T22:21:02+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:02 volumio go-librespot[27417]: time="2026-01-27T22:21:02+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:02 volumio go-librespot[27417]: time="2026-01-27T22:21:02+07:00" level=debug msg="completed challenge" Jan 27 22:21:02 volumio go-librespot[27417]: time="2026-01-27T22:21: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 22:21:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:03 volumio volumio[27099]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:03 volumio volumio[27099]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:21:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 22:21:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:05 volumio go-librespot[27428]: go-librespot daemon starting... Jan 27 22:21:05 volumio go-librespot[27429]: time="2026-01-27T22:21:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:05 volumio go-librespot[27429]: time="2026-01-27T22:21:05+07:00" level=debug msg="app state loaded" Jan 27 22:21:05 volumio go-librespot[27429]: time="2026-01-27T22:21:05+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21: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-gew1.spotify.com:80]" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+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 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+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 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+07:00" level=info msg="zeroconf server listening on port 43675" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+07:00" level=debug msg="obtained new client token: AACUsSvQ8t/rX6igz3K8GjzD3tC0yW/qcFzzVehv9P10fOe/jOTbspqeGppNYoKiPY3oVbj+mJODjO8K1tkhBnKzxdL7yuQH6dEBtGWZvIInU1orapuCx4OC2BnqxVYua1L/xsdQgxK8QnS/E9lebMPCHpU4bSYrHRfYrLtP/SFySoxzUg3nnla6vS1nRtsI93KAOJMRidoVOHz+tDBwy5dnYW3mFvSOUtjPWlg1o4c/PGfkQuVI6VU3" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:06 volumio volumio[27099]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+07:00" level=debug msg="completed challenge" Jan 27 22:21:06 volumio go-librespot[27429]: time="2026-01-27T22:21:06+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 22:21:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:06 volumio volumio[27099]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:06 volumio volumio[27099]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:21:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 22:21:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:09 volumio go-librespot[27436]: go-librespot daemon starting... Jan 27 22:21:09 volumio go-librespot[27437]: time="2026-01-27T22:21:09+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:09 volumio go-librespot[27437]: time="2026-01-27T22:21:09+07:00" level=debug msg="app state loaded" Jan 27 22:21:09 volumio go-librespot[27437]: time="2026-01-27T22:21:09+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:09 volumio volumio[27099]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:09 volumio go-librespot[27437]: time="2026-01-27T22:21:09+07:00" level=debug msg="new websocket client" Jan 27 22:21:10 volumio volumio[27099]: info: Connection to go-librespot Websocket established Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+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 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+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 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+07:00" level=info msg="zeroconf server listening on port 46481" Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 22:21:10 volumio volumio[27099]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+07:00" level=debug msg="obtained new client token: AACT8iK51HWDjj/siJqzCFsD86zk41SRctwby6PYaJb1D2/bbd0YZLpANAsVg+Ib0z+cb2WiNjxKp/kO/sJagyo3OcsKwpbaHrp96DITH7TSNcWRr18lLMM3uX0Ap+pwz6gsirpNu97jIYx+5uBn+sPiKhKe0z4XXuyiU1V2yLbfW0HI4vFpIm4P3WqMPZNR0hyfzw1kf1RUJwyxjDmFM0e2htkCPm3RVrWbaC1Tdfqzu2rVjtP0nPyJRdA=" Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+07:00" level=debug msg="completed challenge" Jan 27 22:21:10 volumio go-librespot[27437]: time="2026-01-27T22:21:10+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 22:21:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:12 volumio volumio[27099]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 22:21:12 volumio volumio[27099]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 22:21:12 volumio volumio[27099]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:12 volumio volumio[27099]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:12 volumio volumio[27099]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 22:21:12 volumio volumio[27099]: info: MyVolumio login type: Token Jan 27 22:21:12 volumio volumio[27099]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 22:21:12 volumio volumio[27099]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 22:21:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 22:21:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:14 volumio go-librespot[27458]: go-librespot daemon starting... Jan 27 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+07:00" level=debug msg="app state loaded" Jan 27 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:14 volumio volumio[27099]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 22:21:14 volumio volumio[27099]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 22:21:14 volumio volumio[27099]: info: Streaming services startup Jan 27 22:21:14 volumio volumio[27099]: info: Starting Streaming Daemon Jan 27 22:21:14 volumio sudo[27467]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 22:21:14 volumio sudo[27467]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:14 volumio volumio[27099]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 22:21:14 volumio sudo[27467]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:14 volumio volumio[27099]: info: Getting Spotify volume Jan 27 22:21:14 volumio volumio[27099]: info: Connection to go-librespot Websocket closed Jan 27 22:21:14 volumio volumio[27099]: error: Cannot start Volumio Streaming Daemon Jan 27 22:21:14 volumio volumio[27099]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 22:21:14 volumio volumio[27099]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 22:21:14 volumio volumio[27099]: 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 22:21:14 volumio volumio[27099]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:14 volumio volumio[27099]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+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 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+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 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+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 22:21:14 volumio volumio[27099]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 22:21:14 volumio volumio[27099]: SPOTIFY: SPOTIFY VOLUME undefined Jan 27 22:21:14 volumio volumio[27099]: SPOTIFY: VOLUMIO VOLUME 100 Jan 27 22:21:14 volumio volumio[27099]: info: Aligning Spotify Volume to Volumio Volume Jan 27 22:21:14 volumio volumio[27099]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:14 volumio volumio[27099]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:14 volumio volumio[27099]: info: Setting Spotify Volume from Volumio: 100 Jan 27 22:21:14 volumio go-librespot[27459]: time="2026-01-27T22:21:14+07:00" level=info msg="zeroconf server listening on port 46501" Jan 27 22:21:15 volumio go-librespot[27459]: time="2026-01-27T22:21:15+07:00" level=debug msg="obtained new client token: AABqy+GANUmUYj3MinslmIUprNWQjIm4huekhmijmGnefkke1XpA283uwAA1/7FM9Fk72JaVKRZXolrSF8rJAfI/0wAmdx39pIDC0hB5g7uU/M5tajgIkUSMSvzcUFWhkdBJehXqvbBWIM4jZBxpmaNvQaAkHGPIivO3gLPSR2ZZH7FC/q2/eboucpnqO+G7zfojIPSxUtwvfNKgapQ492yih3zMfUuC7IJpooYEkytfUYoznwyM7j5EU30=" Jan 27 22:21:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:15 volumio go-librespot[27459]: time="2026-01-27T22:21:15+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:15 volumio go-librespot[27459]: time="2026-01-27T22:21:15+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:15 volumio go-librespot[27459]: time="2026-01-27T22:21:15+07:00" level=debug msg="completed challenge" Jan 27 22:21:15 volumio go-librespot[27459]: time="2026-01-27T22:21:15+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 22:21:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:15 volumio volumio[27099]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:21:15 volumio volumio[27099]: Error: socket hang up Jan 27 22:21:15 volumio volumio[27099]: at connResetException (node:internal/errors:720:14) Jan 27 22:21:15 volumio volumio[27099]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 27 22:21:15 volumio volumio[27099]: at Socket.emit (node:events:526:35) Jan 27 22:21:15 volumio volumio[27099]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 27 22:21:15 volumio volumio[27099]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 27 22:21:15 volumio volumio[27099]: code: 'ECONNRESET', Jan 27 22:21:15 volumio volumio[27099]: response: undefined Jan 27 22:21:15 volumio volumio[27099]: } Jan 27 22:21:15 volumio volumio[27099]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:21:16 volumio sudo[27489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:20' Jan 27 22:21:16 volumio sudo[27489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:17 volumio sudo[27489]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:17 volumio volumio-remote-updater[628]: [2026-01-27 22:21:17] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 27 22:21:17 volumio volumio-remote-updater[628]: [2026-01-27 22:21:17] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 27 22:21:17 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:17 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 22:21:17 volumio systemd[1]: volumio.service: Consumed 58.739s CPU time. Jan 27 22:21:17 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:21:17 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:21:17 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 9232. Jan 27 22:21:17 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:21:17 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 22:21:17 volumio systemd[1]: volumio.service: Consumed 58.739s CPU time. Jan 27 22:21:17 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 22:21:17 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:21:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 27 22:21:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:18 volumio go-librespot[27516]: go-librespot daemon starting... Jan 27 22:21:18 volumio go-librespot[27517]: time="2026-01-27T22:21:18+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:18 volumio go-librespot[27517]: time="2026-01-27T22:21:18+07:00" level=debug msg="app state loaded" Jan 27 22:21:18 volumio go-librespot[27517]: time="2026-01-27T22:21:18+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+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 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+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 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+07:00" level=info msg="zeroconf server listening on port 45379" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+07:00" level=debug msg="obtained new client token: AAD6haGSggUv86PTuil2+iQWXpYKSFEVnAMPPUyLrqD6GOSdx8zn3rIowKz00LhwY9alFOndD83po5F15oPEdmz0gSOOLLkzRgMcBFGdtk3TIQgSWz55gUZITq25ktvy9aZT49U+fShSWjePncrA/FkzpITEQUPfbf1sy1Vl3bU1YkNl7g6GheggoqBcHKDr0VhVt/CnxQkkvqW09/nhUT90xMLzotdcjpV59K8dKMKIM3fvZhsPgpWBwkA=" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21:19+07:00" level=debug msg="completed challenge" Jan 27 22:21:19 volumio go-librespot[27517]: time="2026-01-27T22:21: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 22:21:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:21 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:21 volumio volumio[27501]: info: ----- Volumio3 ---- Jan 27 22:21:21 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:21 volumio volumio[27501]: info: ----- System startup ---- Jan 27 22:21:21 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:22 volumio volumio-remote-updater[628]: [2026-01-27 22:21:22] [connect] Successful connection Jan 27 22:21:22 volumio volumio[27501]: info: MYVOLUMIO Environment detected Jan 27 22:21:22 volumio volumio[27501]: info: Plugin folders cleanup Jan 27 22:21:22 volumio volumio[27501]: info: Scanning into folder /volumio/app/plugins/ Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category audio_interface Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category miscellanea Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category music_service Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category plugins.json Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category system_controller Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category user_interface Jan 27 22:21:22 volumio volumio[27501]: info: Scanning into folder /data/plugins/ Jan 27 22:21:22 volumio volumio[27501]: info: Scanning category music_service Jan 27 22:21:22 volumio volumio[27501]: info: Plugin folders cleanup completed Jan 27 22:21:22 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:22 volumio volumio[27501]: info: ----- Core plugins startup ---- Jan 27 22:21:22 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:22 volumio volumio[27501]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 22:21:22 volumio volumio[27501]: info: Adding plugin upnp to MyMusic Plugins Jan 27 22:21:22 volumio volumio[27501]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 22:21:22 volumio volumio[27501]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 22:21:22 volumio volumio[27501]: info: Loading plugins from folder /data/plugins/ Jan 27 22:21:22 volumio volumio[27501]: info: Loading plugin "system"... Jan 27 22:21:22 volumio volumio[27501]: info: Loading plugin "appearance"... Jan 27 22:21:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 27 22:21:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:22 volumio go-librespot[27536]: go-librespot daemon starting... Jan 27 22:21:22 volumio go-librespot[27537]: time="2026-01-27T22:21:22+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:22 volumio go-librespot[27537]: time="2026-01-27T22:21:22+07:00" level=debug msg="app state loaded" Jan 27 22:21:22 volumio go-librespot[27537]: time="2026-01-27T22:21:22+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21: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 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21: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 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21: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 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21:23+07:00" level=info msg="zeroconf server listening on port 33083" Jan 27 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21:23+07:00" level=debug msg="obtained new client token: AABW2hGaNxHSx6vkfowsw6kYML/N1hijIVo2iazXFQ9kqSUqjJYPZsWup2D96eClLMUQlQt6RXUFP9bG7qRUO9Rt3cwqWf726kqiKUKXqMWvnPJLZiI+wB1mdsCzW3vh2osXaeOHpjIEAr7LT8l3ARKbTRTNEtlm/NO1hIqPWcB6gzkXneTC93riIC/EIBiOPRC/zWT3INOebfPAoMjfqir4APLlwZUy9dKo/wE2jmlLknj6MjvUmKZFwH8=" Jan 27 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21:23+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:23 volumio go-librespot[27537]: time="2026-01-27T22:21:23+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 22:21:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:24 volumio volumio[27501]: info: Loading plugin "network"... Jan 27 22:21:24 volumio volumio[27501]: info: Refreshing Cached IP Addresses Jan 27 22:21:24 volumio sudo[27546]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:21:24 volumio sudo[27546]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:24 volumio sudo[27548]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:21:24 volumio sudo[27548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:24 volumio sudo[27546]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:24 volumio volumio[27501]: info: Loading plugin "services"... Jan 27 22:21:24 volumio volumio[27501]: info: Loading plugin "alsa_controller"... Jan 27 22:21:24 volumio sudo[27548]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:24 volumio sudo[27555]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 22:21:24 volumio sudo[27555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:24 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:21:24 volumio volumio[27501]: info: Loading plugin "wizard"... Jan 27 22:21:24 volumio volumio[27501]: info: Loading plugin "networkfs"... Jan 27 22:21:25 volumio volumio[27501]: info: Starting Udev Watcher for removable devices Jan 27 22:21:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:25 volumio volumio[27501]: info: Ignoring mount for partition: boot Jan 27 22:21:25 volumio volumio[27501]: info: Ignoring mount for partition: volumio Jan 27 22:21:25 volumio volumio[27501]: info: Ignoring mount for partition: volumio_data Jan 27 22:21:25 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:21:25 volumio volumio[27501]: info: Loading plugin "volumio_command_line_client"... Jan 27 22:21:25 volumio volumio[27501]: info: Loading plugin "upnp"... Jan 27 22:21:25 volumio volumio[27501]: info: [1769527285116] Starting Upmpd Daemon Jan 27 22:21:25 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:21:25 volumio volumio[27501]: info: Loading plugin "my_music"... Jan 27 22:21:25 volumio volumio[27501]: info: Loading plugin "mpd"... Jan 27 22:21:25 volumio volumio[27501]: info: Loading plugin "upnp_browser"... Jan 27 22:21:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 27 22:21:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:27 volumio go-librespot[27579]: go-librespot daemon starting... Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=debug msg="app state loaded" Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+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 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+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 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=info msg="zeroconf server listening on port 45757" Jan 27 22:21:27 volumio sudo[27555]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=debug msg="obtained new client token: AACcob/X51CLuQ6cfq0qNigXHzawm8MGcyHRAznwaYwVbXr7UYvswAaof5Ojrik7fYLJpeS4XRLmnMJKj5gxiOMQH5Cp2pSM0hlFfcrDdtnbiS8kgenMQ4pY6OaaAoud9c5c7NkwMzOncsiI0DHyURTmAwzMFDIYmcXGemqfh/Ek20hVqULdssH43odKB9yHCCPdr7BxspA07/U8X7vol/DEM6ARbaW4CGMcp76iZO7BqqYywna6RH8RyYU=" Jan 27 22:21:27 volumio go-librespot[27580]: time="2026-01-27T22:21:27+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:28 volumio go-librespot[27580]: time="2026-01-27T22:21:28+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:28 volumio go-librespot[27580]: time="2026-01-27T22:21:28+07:00" level=debug msg="completed challenge" Jan 27 22:21:28 volumio go-librespot[27580]: time="2026-01-27T22:21:28+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 22:21:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:28 volumio volumio[27501]: info: Starting UPNP Browser Jan 27 22:21:28 volumio volumio[27501]: info: Loading plugin "alarm-clock"... Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "airplay_emulation"... Jan 27 22:21:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:29 volumio volumio[27501]: info: Starting Shairport Sync Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "last_100"... Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "webradio"... Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "i2s_dacs"... Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "volumiodiscovery"... Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** For more information see Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:21:29 volumio volumio[27501]: *** WARNING *** For more information see Jan 27 22:21:29 volumio node[27501]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:21:29 volumio node[27501]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:21:29 volumio node[27501]: *** WARNING *** For more information see Jan 27 22:21:29 volumio node[27501]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:21:29 volumio node[27501]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:21:29 volumio node[27501]: *** WARNING *** For more information see Jan 27 22:21:29 volumio volumio[27501]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 22:21:29 volumio volumio[27501]: info: Discovery: Started advertising with name: Volumio Jan 27 22:21:29 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:21:29 volumio volumio[27501]: info: Loading plugin "spop"... Jan 27 22:21:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:31 volumio volumio[27501]: info: Loading plugin "ytcr"... Jan 27 22:21:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 27 22:21:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:31 volumio go-librespot[27590]: go-librespot daemon starting... Jan 27 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+07:00" level=debug msg="app state loaded" Jan 27 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+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 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+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 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+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 22:21:31 volumio go-librespot[27591]: time="2026-01-27T22:21:31+07:00" level=info msg="zeroconf server listening on port 39827" Jan 27 22:21:32 volumio go-librespot[27591]: time="2026-01-27T22:21:32+07:00" level=debug msg="obtained new client token: AADjNoFNki7wsJZagHjPlEZuplE1MK3cdHuEbDQl24vdOQdX7mRwW+Y7ipwdTmcuIHyWcPJscqsqBkmDQm2gK4wruk328zbHzisL4MSo3PmifEJeE0lUgBrY07JUq2+G/+/UuVqu3aKUz9zR5cLTApKgLQhBbEe8WS3yK8t6L51J/AOx0oh5E5bTor3VJp9hqEgghltzb7iAfFLxaQAJhp7jWTvJt14xkOfkaaP6vk21KDGO42OtAVEK" Jan 27 22:21:32 volumio go-librespot[27591]: time="2026-01-27T22:21:32+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:32 volumio go-librespot[27591]: time="2026-01-27T22:21:32+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:32 volumio go-librespot[27591]: time="2026-01-27T22:21:32+07:00" level=debug msg="completed challenge" Jan 27 22:21:32 volumio go-librespot[27591]: time="2026-01-27T22:21:32+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 22:21:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:33 volumio volumio[27501]: info: Loading plugin "ytmusic"... Jan 27 22:21:34 volumio volumio-remote-updater[628]: [2026-01-27 22:21:34] [connect] Successful connection Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "outputs"... Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "albumart"... Jan 27 22:21:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:35 volumio volumio[27501]: info: Plugin example_plugin is not enabled Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "inputs"... Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "updater_comm"... Jan 27 22:21:35 volumio volumio[27501]: info: Plugin mpdemulation is not enabled Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "rest_api"... Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "websocket"... Jan 27 22:21:35 volumio volumio[27501]: info: Starting Socket.io Server version 1.7.4 Jan 27 22:21:35 volumio volumio[27501]: info: Loading plugin "RoonBridge"... Jan 27 22:21:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 27 22:21:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:35 volumio go-librespot[27622]: go-librespot daemon starting... Jan 27 22:21:35 volumio volumio[27501]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 22:21:35 volumio go-librespot[27623]: time="2026-01-27T22:21:35+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:35 volumio go-librespot[27623]: time="2026-01-27T22:21:35+07:00" level=debug msg="app state loaded" Jan 27 22:21:35 volumio go-librespot[27623]: time="2026-01-27T22:21:35+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:35 volumio volumio[27501]: info: Loading i18n strings for locale en Jan 27 22:21:35 volumio volumio[27501]: Updating browse sources language Jan 27 22:21:35 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::initPlayerControls Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:21:36 volumio volumio[27501]: Express server listening on port 3000 Jan 27 22:21:36 volumio volumio[27612]: Forking 3 albumart workers Jan 27 22:21:36 volumio volumio[27501]: [Metrics] WebUI: 16s 132.53ms Jan 27 22:21:36 volumio volumio[27501]: info: CoreStateMachine::resetVolumioState Jan 27 22:21:36 volumio volumio[27501]: info: CoreStateMachine::getcurrentVolume Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+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 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+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 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+07:00" level=info msg="zeroconf server listening on port 34961" Jan 27 22:21:36 volumio sudo[27652]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:21:36 volumio sudo[27652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:36 volumio sudo[27666]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:21:36 volumio sudo[27666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:36 volumio sudo[27652]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:36 volumio sudo[27666]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:36 volumio volumio[27501]: info: Volumio Network Manager: Network status updated: 1 Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+07:00" level=debug msg="obtained new client token: AAB+UPi4uDD7yglyBFO2EoXvbQ/xAVF5X+qsDRIHepLOmhQZglmUwpgDbUsEtXa1Ze5FFg/Zg3+b16qF1JuBBxm9z0MbwJBU7HLVQQyjgH23DZ0XsfM5ceo87Dbo7BSZGLyOQYuVJiqzxviVLQlW+lXO1/rX4em6X7bd0DHGAbSJ5j8k6SRPvnUaavpty3X+c1uKbNhuZudfWQ/Sy/oaassRdu3CiQiMLErX+5fGobMm107y2j4XMkZjXpo=" Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21:36+07:00" level=debug msg="completed challenge" Jan 27 22:21:36 volumio volumio[27501]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:21:36 volumio volumio[27501]: info: CoreStateMachine::pushState Jan 27 22:21:36 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::volumioPushState Jan 27 22:21:36 volumio volumio[27501]: info: CoreStateMachine::updateTrackBlock Jan 27 22:21:36 volumio volumio[27501]: info: CorePlayQueue::getTrackBlock Jan 27 22:21:36 volumio volumio[27501]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:21:36 volumio go-librespot[27623]: time="2026-01-27T22:21: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 22:21:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:37 volumio volumio-remote-updater[628]: [2026-01-27 22:21:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769527294 101 Jan 27 22:21:37 volumio volumio[27501]: 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 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:37 volumio volumio[27501]: info: Reloading queue from file Jan 27 22:21:37 volumio volumio[27501]: info: CoreStateMachine::setRepeat null single undefined Jan 27 22:21:37 volumio volumio[27501]: info: CoreStateMachine::pushState Jan 27 22:21:37 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::volumioPushState Jan 27 22:21:37 volumio volumio[27501]: info: CoreStateMachine::setRandom null Jan 27 22:21:37 volumio volumio[27501]: info: CoreStateMachine::pushState Jan 27 22:21:37 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::volumioPushState Jan 27 22:21:37 volumio volumio[27501]: info: Setting Device type: Raspberry PI Jan 27 22:21:37 volumio volumio[27501]: info: Completed loading Core Plugins Jan 27 22:21:37 volumio volumio[27501]: info: Preparing to generate the ALSA configuration file Jan 27 22:21:37 volumio volumio[27501]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:21:37 volumio volumio[27501]: info: CoreStateMachine::pushState Jan 27 22:21:37 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::volumioPushState Jan 27 22:21:37 volumio volumio[27501]: info: Asound.conf file unchanged, so no further update is needed Jan 27 22:21:37 volumio volumio[27501]: info: Output device has changed, restarting MPD Jan 27 22:21:37 volumio volumio[27501]: info: Output device has changed, restarting Shairport Sync Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:37 volumio sudo[27682]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 22:21:37 volumio sudo[27682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:37 volumio sudo[27684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:21:37 volumio sudo[27684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:37 volumio volumio[27501]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:21:37 volumio volumio[27501]: info: ___________ START PLUGINS ___________ Jan 27 22:21:37 volumio sudo[27684]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:37 volumio volumio[27501]: info: ControllerMpd::onStart: Initializing MPD Jan 27 22:21:37 volumio volumio[27501]: info: Creating MPD Configuration file Jan 27 22:21:37 volumio sudo[27686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:21:37 volumio sudo[27686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:21:37 volumio volumio[27501]: info: [1769527297732] CoreMusicLibrary::Adding element Media Servers Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:37 volumio volumio[27501]: info: UPNP Browser: Client initialized successfully Jan 27 22:21:37 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 22:21:37 volumio sudo[27682]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:37 volumio sudo[27695]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:37 volumio sudo[27695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:37 volumio sudo[27695]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:37 volumio sudo[27697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:21:37 volumio volumio[27501]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:21:37 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:21:37 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:21:37 volumio systemd[1]: mpd.service: Consumed 7.418s CPU time. Jan 27 22:21:37 volumio sudo[27697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:37 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:37 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:21:37 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:21:37 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:21:38 volumio volumio[27501]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:21:38 volumio volumio[27501]: info: [1769527298017] CoreMusicLibrary::Adding element Last_100 Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:21:38 volumio volumio[27501]: info: [1769527298026] CoreMusicLibrary::Adding element Webradio Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:21:38 volumio volumio[27501]: info: Initializing BBC Radios Jan 27 22:21:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:21:38 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:21:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:21:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:21:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:21:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:21:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:21:38 volumio volumio[27501]: info: Creating Spotify config file Jan 27 22:21:38 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:38 volumio sudo[27726]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 22:21:38 volumio sudo[27726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 22:21:38 volumio sudo[27726]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:39 volumio volumio[27633]: Starting albumart workers Jan 27 22:21:39 volumio volumio[27501]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:21:39 volumio volumio[27501]: info: [1769527299611] CoreMusicLibrary::Adding element YouTube Music Jan 27 22:21:39 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:39 volumio volumio[27501]: Cannot find translation for source YouTube Music Jan 27 22:21:39 volumio volumio[27501]: info: Volumio Calling Home Jan 27 22:21:39 volumio volumio[27637]: Starting albumart workers Jan 27 22:21:39 volumio sudo[27730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 22:21:39 volumio sudo[27730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:39 volumio sudo[27730]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:40 volumio volumio[27636]: Starting albumart workers Jan 27 22:21:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 27 22:21:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:40 volumio go-librespot[27735]: go-librespot daemon starting... Jan 27 22:21:40 volumio go-librespot[27736]: time="2026-01-27T22:21:40+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:40 volumio go-librespot[27736]: time="2026-01-27T22:21:40+07:00" level=debug msg="app state loaded" Jan 27 22:21:40 volumio go-librespot[27736]: time="2026-01-27T22:21:40+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:40 volumio volumio[27501]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:21:40 volumio volumio[27501]: info: Discovery: Found device Volumio Jan 27 22:21:40 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:40 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:40 volumio volumio[27501]: info: MPD Permissions set Jan 27 22:21:40 volumio volumio[27501]: info: MPD Permissions set Jan 27 22:21:40 volumio volumio[27501]: info: Upmpdcli Daemon Started Jan 27 22:21:40 volumio volumio[27501]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:21:40 volumio volumio[27501]: info: Discovery: Found device Volumio Jan 27 22:21:40 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:40 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:40 volumio volumio[27501]: info: Volumio called home Jan 27 22:21:40 volumio volumio[27501]: info: Spotify config file written Jan 27 22:21:40 volumio sudo[27744]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 22:21:40 volumio sudo[27744]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:41 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 22:21:41 volumio systemd[1]: go-librespot-daemon.service: Killing process 27745 (go-librespot) with signal SIGKILL. Jan 27 22:21:41 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 22:21:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:41 volumio go-librespot[27748]: go-librespot daemon starting... Jan 27 22:21:41 volumio sudo[27744]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+07:00" level=debug msg="app state loaded" Jan 27 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:41 volumio volumio[27501]: 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 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:21:41 volumio volumio[27501]: info: No need to fix Spotify hosts Jan 27 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+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 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+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 22:21:41 volumio go-librespot[27749]: time="2026-01-27T22:21:41+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 22:21:42 volumio go-librespot[27749]: time="2026-01-27T22:21:42+07:00" level=info msg="zeroconf server listening on port 41307" Jan 27 22:21:42 volumio go-librespot[27749]: time="2026-01-27T22:21:42+07:00" level=debug msg="obtained new client token: AADDD62DXVx9WCiHJzF4OrRvuVckDB8Q8PJyUJzj78ZzPapPYQ6S+VLoIpghpJgdilni78sbftX66DGQ1r3AgJoalV+fPVC3cTAbnE8TW1VOnUsKVzXWtjrAt0vYvGmXkBv6SZCwheP19rEwTiNJhswi573FHq7DE9oTtSLiHyGqAkCgBbz5hsFa6eK+vVed5euZT+8J8GcFyRZXvQQknLZG/GA+W+mNcfzijsdoDsE5BGi27qNSuokR" Jan 27 22:21:42 volumio go-librespot[27749]: time="2026-01-27T22:21:42+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:42 volumio go-librespot[27749]: time="2026-01-27T22:21:42+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 22:21:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:42 volumio volumio[27501]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:21:42 volumio volumio[27501]: SPOTIFY: BQBSjDGJMXELQCMk_4De2tQpThAWxErC3mTwe0UpxjIIxdqbFWj1O-I2Uo96tGjTpLDb77ZVmeN6fqH4qSNFRV2UG2c6_P-NLIA_VrxEhQrO0aBV-uGX-GDOxdhDNqz6_NEq-pbi3ExwXJUt-XFXKbDfU_HpXj4fTuvlr78eIuzasiWeMGMdDPcWNKNBlq36y6wBoL9R1SANc8UjRDwynKUMfgBX05TrmVjfTVedORfH6-8GveRGj3bT7bELiV5-KP4DIttKNxA4pHbpwm2kg4cuYJvr_PIcekZhVsoQWrWvXsl_1jku3_RE Jan 27 22:21:42 volumio volumio[27501]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:21:42 volumio volumio[27501]: info: New Spotify access token = BQBSjDGJMXELQCMk_4De2tQpThAWxErC3mTwe0UpxjIIxdqbFWj1O-I2Uo96tGjTpLDb77ZVmeN6fqH4qSNFRV2UG2c6_P-NLIA_VrxEhQrO0aBV-uGX-GDOxdhDNqz6_NEq-pbi3ExwXJUt-XFXKbDfU_HpXj4fTuvlr78eIuzasiWeMGMdDPcWNKNBlq36y6wBoL9R1SANc8UjRDwynKUMfgBX05TrmVjfTVedORfH6-8GveRGj3bT7bELiV5-KP4DIttKNxA4pHbpwm2kg4cuYJvr_PIcekZhVsoQWrWvXsl_1jku3_RE Jan 27 22:21:42 volumio volumio[27501]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 22:21:42 volumio volumio[27501]: info: Starting Shairport Sync Jan 27 22:21:42 volumio volumio[27501]: info: Starting Shairport Sync Jan 27 22:21:42 volumio volumio[27501]: info: Starting Shairport Sync Jan 27 22:21:42 volumio sudo[27786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:21:42 volumio sudo[27786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:42 volumio sudo[27788]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:21:42 volumio sudo[27788]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:42 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 22:21:43 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 22:21:43 volumio sudo[27791]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:21:43 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:21:43 volumio systemd[1]: shairport-sync.service: Consumed 2.317s CPU time. Jan 27 22:21:43 volumio sudo[27791]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:43 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:21:43 volumio sudo[27786]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:43 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 22:21:43 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 22:21:43 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:21:43 volumio volumio[27501]: info: Shairport-Sync Started Jan 27 22:21:43 volumio volumio[27501]: Error adding Membership: Error: addMembership EINVAL Jan 27 22:21:43 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:43 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:43 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:21:43 volumio sudo[27788]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:43 volumio sudo[27791]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:43 volumio volumio[27501]: info: Shairport-Sync Started Jan 27 22:21:43 volumio volumio[27501]: info: Shairport-Sync Started Jan 27 22:21:43 volumio volumio[27501]: 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 22:21:43 volumio volumio[27501]: info: Spotify Successfully logged in Jan 27 22:21:43 volumio volumio[27501]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:21:43 volumio volumio[27501]: info: [1769527303555] CoreMusicLibrary::Adding element Spotify Jan 27 22:21:43 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:21:43 volumio volumio[27501]: Cannot find translation for source YouTube Music Jan 27 22:21:43 volumio volumio[27501]: Cannot find translation for source Spotify Jan 27 22:21:44 volumio volumio[27501]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 22:21:44 volumio volumio[27501]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:21:44 volumio volumio[27501]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:21:44 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:44 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:44 volumio volumio[27501]: info: CoreStateMachine::pushState Jan 27 22:21:44 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:44 volumio volumio[27501]: info: CoreCommandRouter::volumioPushState Jan 27 22:21:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 22:21:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:45 volumio volumio[27501]: info: go-librespot daemon successfully initialized Jan 27 22:21:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:45 volumio go-librespot[27840]: go-librespot daemon starting... Jan 27 22:21:45 volumio go-librespot[27841]: time="2026-01-27T22:21:45+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:45 volumio go-librespot[27841]: time="2026-01-27T22:21:45+07:00" level=debug msg="app state loaded" Jan 27 22:21:45 volumio go-librespot[27841]: time="2026-01-27T22:21:45+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:45 volumio mpd[27728]: 2026-01-27T22:21:45 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 22:21:45 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 22:21:46 volumio sudo[27697]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:46 volumio sudo[27686]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+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 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+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 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+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 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+07:00" level=info msg="zeroconf server listening on port 37545" Jan 27 22:21:46 volumio volumio[27501]: error: MPD error: The expression evaluated to a falsy value: Jan 27 22:21:46 volumio volumio[27501]: assert.ok(self.idling) Jan 27 22:21:46 volumio volumio[27501]: error: The expression evaluated to a falsy value: Jan 27 22:21:46 volumio volumio[27501]: assert.ok(self.idling) Jan 27 22:21:46 volumio volumio[27501]: error: updateQueue error: null Jan 27 22:21:46 volumio volumio[27501]: info: MPD running with PID27728 Jan 27 22:21:46 volumio volumio[27501]: ,establishing connection Jan 27 22:21:46 volumio volumio[27501]: info: Completed starting Core Plugins Jan 27 22:21:46 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:46 volumio volumio[27501]: info: ----- MyVolumio plugins startup ---- Jan 27 22:21:46 volumio volumio[27501]: info: ------------------------------------------- Jan 27 22:21:46 volumio volumio[27501]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 22:21:46 volumio volumio[27501]: error: updateQueue error: null Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+07:00" level=debug msg="obtained new client token: AACiCdi/8qxgc6p//eK3LgX83WthpMroZu0cpe4oLvM6AiNNDxZGF8QTey3WFqF/oLxuXK5oGPy8oqO7XRnjEuxWkLAB8xRcSGCeLypFfyrUYp75Gb/y+8u/J+Nd/uuZ0MaGWdPawtReauDNnAe76ZGnWPULZ96kKoQigp7vC7LrAOzOVpuhlG3sskU8JajC3WlibTwszMXhSZ0FK+ibGx3vegefeRE4J5jPnDFa8JNyC75eD0VP5f/FvrA=" Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+07:00" level=debug msg="completed challenge" Jan 27 22:21:46 volumio go-librespot[27841]: time="2026-01-27T22:21:46+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 22:21:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:48 volumio volumio[27501]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:48 volumio volumio[27501]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:21:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 22:21:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:50 volumio go-librespot[27853]: go-librespot daemon starting... Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=debug msg="app state loaded" Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+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 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+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 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+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 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=info msg="zeroconf server listening on port 34377" Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=debug msg="obtained new client token: AACZxz1Cobrgra467968yGHbsD1gy3C8F5sI5/SNTqh4V6D9EP8j/K+tmOh4JsikspS3GRUDL0+TBQKQozugX4SG1N1buh7hX953Cwvm2nFJnG0p6i5ZqSE2Md9LJhlph+4boQ5H69rDM2AmR3bxPEv3dV+UhtppujY++P9iqVbsQB3AlVZQ0gX7dn23u5ceLxX+zyBCrD9wxw7GeJtVQLoCWZs1xb9zcQSSp2VsdbQyP/9gojAzWEt9KeA=" Jan 27 22:21:50 volumio go-librespot[27854]: time="2026-01-27T22:21:50+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:51 volumio go-librespot[27854]: time="2026-01-27T22:21:51+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:51 volumio go-librespot[27854]: time="2026-01-27T22:21:51+07:00" level=debug msg="completed challenge" Jan 27 22:21:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:51 volumio volumio[27501]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 22:21:51 volumio go-librespot[27854]: time="2026-01-27T22:21:51+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 22:21:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:51 volumio volumio[27501]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:51 volumio volumio[27501]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:21:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 22:21:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:54 volumio go-librespot[27863]: go-librespot daemon starting... Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+07:00" level=debug msg="app state loaded" Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:54 volumio volumio[27501]: info: Initializing connection to go-librespot Websocket Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+07:00" level=debug msg="new websocket client" Jan 27 22:21:54 volumio volumio[27501]: info: Connection to go-librespot Websocket established Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+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 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+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 22:21:54 volumio go-librespot[27864]: time="2026-01-27T22:21:54+07:00" level=info msg="zeroconf server listening on port 45207" Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+07:00" level=debug msg="obtained new client token: AABknTXyJzth/FPVqbytyXWcQ9w6BN/5R9zVsh+4ZlRdCux2U8yrA0Hox7ixeClV3Y/qxl27iojDhrUXKFQ/C7zbAOTcdDCBum+CYoR/3VdcZErOIFkGrQE0mTrNVR+Anve0pxBd/KwuGHD8tliiQMRbAOyhZoppsz0L5q/M4nnZz0JwM4G/hTYJNYVrhIBl/U2G3SXyL7jmP3kQweU/lcNyHvxsFyivXzOrR8ZsAa2T+XigSvDn6SBw" Jan 27 22:21:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+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 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 22:21:55 volumio volumio[27501]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+07:00" level=debug msg="completed challenge" Jan 27 22:21:55 volumio go-librespot[27864]: time="2026-01-27T22:21:55+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 22:21:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:57 volumio volumio[27501]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 22:21:57 volumio volumio[27501]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 22:21:57 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:57 volumio volumio[27501]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:21:57 volumio volumio[27501]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 22:21:57 volumio volumio[27501]: info: MyVolumio login type: Token Jan 27 22:21:57 volumio volumio[27501]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 22:21:57 volumio volumio[27501]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 22:21:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 22:21:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:21:58 volumio go-librespot[27887]: go-librespot daemon starting... Jan 27 22:21:58 volumio go-librespot[27888]: time="2026-01-27T22:21:58+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:21:58 volumio go-librespot[27888]: time="2026-01-27T22:21:58+07:00" level=debug msg="app state loaded" Jan 27 22:21:58 volumio go-librespot[27888]: time="2026-01-27T22:21:58+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:21:58 volumio volumio[27501]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 22:21:58 volumio volumio[27501]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 22:21:58 volumio volumio[27501]: info: Streaming services startup Jan 27 22:21:58 volumio volumio[27501]: info: Starting Streaming Daemon Jan 27 22:21:59 volumio volumio[27501]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 22:21:59 volumio sudo[27896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 22:21:59 volumio sudo[27896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:21:59 volumio sudo[27896]: pam_unix(sudo:session): session closed for user root Jan 27 22:21:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:21:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:21:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+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 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+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 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+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 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+07:00" level=info msg="zeroconf server listening on port 38301" Jan 27 22:21:59 volumio volumio[27501]: info: Getting Spotify volume Jan 27 22:21:59 volumio volumio[27501]: info: Connection to go-librespot Websocket closed Jan 27 22:21:59 volumio volumio[27501]: error: Cannot start Volumio Streaming Daemon Jan 27 22:21:59 volumio volumio[27501]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 22:21:59 volumio volumio[27501]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 22:21:59 volumio volumio[27501]: 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 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+07:00" level=debug msg="obtained new client token: AAClBHjlpTGR72Q4dJb6dyeIP66d0qR6mxOUyN1Cd+mTDa2B1yXC3txeCNABOAQB5xpFJXjibsfk06aTDBe/DbAoefiA9bYjo4R0BoKeGo6ds7WPIj1s4OB7gMXaiRx1uzZXfAyFUHLUsJGbv6NWdZtWpLGrotTjyXFbev91uCcj/ODoQ8w9o/yvXLXku1ZexcJVWS2Ql6gI7usEaVqGRc7JCSHqvWt6Y46RxDPceyPYs2WfdUESyvTAWvo=" Jan 27 22:21:59 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:59 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:59 volumio volumio[27501]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 22:21:59 volumio volumio[27501]: SPOTIFY: SPOTIFY VOLUME undefined Jan 27 22:21:59 volumio volumio[27501]: SPOTIFY: VOLUMIO VOLUME 100 Jan 27 22:21:59 volumio volumio[27501]: info: Aligning Spotify Volume to Volumio Volume Jan 27 22:21:59 volumio volumio[27501]: info: CoreCommandRouter::volumioGetState Jan 27 22:21:59 volumio volumio[27501]: info: CorePlayQueue::getTrack 0 Jan 27 22:21:59 volumio volumio[27501]: info: Setting Spotify Volume from Volumio: 100 Jan 27 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+07:00" level=debug msg="completed keyexchange" Jan 27 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+07:00" level=debug msg="completed challenge" Jan 27 22:21:59 volumio go-librespot[27888]: time="2026-01-27T22:21:59+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 22:21:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:21:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:21:59 volumio volumio[27501]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:21:59 volumio volumio[27501]: Error: socket hang up Jan 27 22:21:59 volumio volumio[27501]: at connResetException (node:internal/errors:720:14) Jan 27 22:21:59 volumio volumio[27501]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 27 22:21:59 volumio volumio[27501]: at Socket.emit (node:events:526:35) Jan 27 22:21:59 volumio volumio[27501]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 27 22:21:59 volumio volumio[27501]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 27 22:21:59 volumio volumio[27501]: code: 'ECONNRESET', Jan 27 22:21:59 volumio volumio[27501]: response: undefined Jan 27 22:21:59 volumio volumio[27501]: } Jan 27 22:21:59 volumio volumio[27501]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:01 volumio sudo[27917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:21' Jan 27 22:22:01 volumio sudo[27917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:01 volumio sudo[27917]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:01 volumio volumio-remote-updater[628]: [2026-01-27 22:22:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 27 22:22:01 volumio volumio-remote-updater[628]: [2026-01-27 22:22:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 27 22:22:01 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:01 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Consumed 58.982s CPU time. Jan 27 22:22:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 9233. Jan 27 22:22:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:01 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Consumed 58.982s CPU time. Jan 27 22:22:01 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 22:22:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 27 22:22:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:02 volumio go-librespot[27947]: go-librespot daemon starting... Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=debug msg="app state loaded" Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+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 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+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 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+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 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=info msg="zeroconf server listening on port 37437" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="obtained new client token: AABOC+J4SJdHXFS7e13tgW9n8WTTxPfF8D+J8v5hyI6CTYwcClvGAeAqkkQZTeC4hCD/hRJ3h7h5Ca5UVEkEArUHCavO3SnytmAAQCl1cjCz54+vwen8c7ylZGAIJXoleqzQEh+39OBO9S0BqX/pEabQRWkUZz+TH9TAfrWQXvRb/KAJMYcqrgvV8zN2ARdiU3sXiR0ovZlXU4Bwo7dUm5wLHouAEzOTZYbkB1dSBdtY7l3rxb2ZcNUVZ84=" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="completed challenge" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22: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 22:22:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:05 volumio volumio[27932]: info: ----- Volumio3 ---- Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:05 volumio volumio[27932]: info: ----- System startup ---- Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:06 volumio volumio-remote-updater[628]: [2026-01-27 22:22:06] [connect] Successful connection Jan 27 22:22:06 volumio volumio[27932]: info: MYVOLUMIO Environment detected Jan 27 22:22:06 volumio volumio[27932]: info: Plugin folders cleanup Jan 27 22:22:06 volumio volumio[27932]: info: Scanning into folder /volumio/app/plugins/ Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category audio_interface Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category miscellanea Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category music_service Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category plugins.json Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category system_controller Jan 27 22:22:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 27 22:22:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category user_interface Jan 27 22:22:06 volumio volumio[27932]: info: Scanning into folder /data/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Scanning category music_service Jan 27 22:22:07 volumio volumio[27932]: info: Plugin folders cleanup completed Jan 27 22:22:07 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:07 volumio volumio[27932]: info: ----- Core plugins startup ---- Jan 27 22:22:07 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin upnp to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugins from folder /data/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugin "system"... Jan 27 22:22:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:07 volumio go-librespot[27965]: go-librespot daemon starting... Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugin "appearance"... Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="app state loaded" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+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 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+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 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="zeroconf server listening on port 36065" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="obtained new client token: AADGWRvvjWdyIRY0TFTsYW7GZK3aH8gT0Zn6iioO+fIojJ9lXwrx507B6n6MK9dfxiKZ6RCx2NP28s02gcQvhzOJiCeGsi1wTEVygADxUjmo5AscCu9PLWVyiRAQwdEF/++QPxDELKSCEIqQNPim8w4N0s1qftWvUInTEth62xN4BWJ8ljIYc+wtT9G126TF/701aH05QUCItzq22bssAlCR+9MjrgMvKL6Hf27SBPtMhOZBPpA8NR7vZsc=" Jan 27 22:22:08 volumio go-librespot[27966]: time="2026-01-27T22:22:08+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:08 volumio go-librespot[27966]: time="2026-01-27T22:22:08+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 22:22:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "network"... Jan 27 22:22:09 volumio volumio[27932]: info: Refreshing Cached IP Addresses Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:09 volumio sudo[27977]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:22:09 volumio sudo[27977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio sudo[27977]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "services"... Jan 27 22:22:09 volumio sudo[27979]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:22:09 volumio sudo[27979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "alsa_controller"... Jan 27 22:22:09 volumio sudo[27987]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 22:22:09 volumio sudo[27987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio sudo[27979]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "wizard"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "networkfs"... Jan 27 22:22:09 volumio volumio[27932]: info: Starting Udev Watcher for removable devices Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: boot Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: volumio Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: volumio_data Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "volumio_command_line_client"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "upnp"... Jan 27 22:22:09 volumio volumio[27932]: info: [1769527329477] Starting Upmpd Daemon Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "my_music"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "mpd"... Jan 27 22:22:10 volumio volumio[27932]: info: Loading plugin "upnp_browser"... Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 27 22:22:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:11 volumio go-librespot[28011]: go-librespot daemon starting... Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=debug msg="app state loaded" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22: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 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22: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 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22: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 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="zeroconf server listening on port 33153" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="obtained new client token: AACbdi5NUQ++y4FPJMShmDLsx20ZoOq3BKRZDtKmpYVHO8jqzHhbisq5Y7H/h5lOYFK1+cupwpUcgzZdFUFlWKTkP8urwU74ULzUWexvjbZWZYSiGsH/66egdz1hlhGd+21+kqAc7qPAZ529JnzpilFqSgskcDzozDt+mNK/SYZT5JXX9rMojTBqyLazndHox8vCDz5XnuSjiSdM6Q5dCU//kQf06iVyWnU8JCKMapjUoBueajWUyjTq" Jan 27 22:22:12 volumio sudo[27987]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="completed challenge" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+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 22:22:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:13 volumio volumio[27932]: info: Starting UPNP Browser Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "alarm-clock"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "airplay_emulation"... Jan 27 22:22:13 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "last_100"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "webradio"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "i2s_dacs"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "volumiodiscovery"... Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio node[27932]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio node[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio node[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio node[27932]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio node[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio node[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio volumio[27932]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 22:22:13 volumio volumio[27932]: info: Discovery: Started advertising with name: Volumio Jan 27 22:22:13 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "spop"... Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 27 22:22:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:15 volumio go-librespot[28021]: go-librespot daemon starting... Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=debug msg="app state loaded" Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:15 volumio volumio[27932]: info: Loading plugin "ytcr"... Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+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 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+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 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+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 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=info msg="zeroconf server listening on port 39963" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="obtained new client token: AAABtY/g2ywzHIT8Pocmqh2Qs2lCOT3lKJNP1xoRpZuazrYQvAhWJNT4Y2Cz6fzgpKuz0B+3P3FX5rhwReD1aEmLQHdfQk76nHBxiuVMwu4Gzxfc9ATB5KJwcGNCC3zbGX8IUGDFY6FQkUCUrvT/mYN4+3v2AVwlqfGtiEq4qdx/96/OZTBFjaXYjZZkp6EECBjdjHwatIbUfcfRvDcMoZOxhP9IQYrW8oSOV+iuVct41ssRRJhtWgZTt4g=" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="completed challenge" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+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 22:22:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:18 volumio volumio[27932]: info: Loading plugin "ytmusic"... Jan 27 22:22:19 volumio volumio-remote-updater[628]: [2026-01-27 22:22:19] [connect] Successful connection Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "outputs"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "albumart"... Jan 27 22:22:19 volumio volumio[27932]: info: Plugin example_plugin is not enabled Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "inputs"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "updater_comm"... Jan 27 22:22:19 volumio volumio[27932]: info: Plugin mpdemulation is not enabled Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "rest_api"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "websocket"... Jan 27 22:22:19 volumio volumio[27932]: info: Starting Socket.io Server version 1.7.4 Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "RoonBridge"... Jan 27 22:22:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 27 22:22:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:20 volumio go-librespot[28055]: go-librespot daemon starting... Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="app state loaded" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:20 volumio volumio[27932]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 22:22:20 volumio volumio[27932]: info: Loading i18n strings for locale en Jan 27 22:22:20 volumio volumio[27932]: Updating browse sources language Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:20 volumio volumio[28045]: Forking 3 albumart workers Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+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 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+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 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="zeroconf server listening on port 42473" Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::initPlayerControls Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: Express server listening on port 3000 Jan 27 22:22:20 volumio volumio[27932]: [Metrics] WebUI: 16s 274.54ms Jan 27 22:22:20 volumio volumio[27932]: info: CoreStateMachine::resetVolumioState Jan 27 22:22:20 volumio volumio[27932]: info: CoreStateMachine::getcurrentVolume Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="obtained new client token: AAATozMoT6ZFAmkDgZB2oGhpLMyCFm8kaH+BmN7EucNpbB5x6ta0XallcNOO2veZON5HXQpjmONKJ3rthzrRGkM3MStjEj7MMKiax2xJq2thHVeiyfF+jGM0XdnOezGUUG44LSWzLQp39Wf5cwwWrl36B0RAe4Jp0eHwWcJTSJrdvutW+Ij2GlcbpP14APCaCdHzWcrqqEwgM723tyCXx41KbfwH7xpgMeo1SSPCKiyAPdM6DSf+k7BTIcA=" Jan 27 22:22:21 volumio go-librespot[28056]: time="2026-01-27T22:22:21+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:21 volumio sudo[28098]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:22:21 volumio sudo[28098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:21 volumio sudo[28098]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:21 volumio volumio[27932]: info: Volumio Network Manager: Network status updated: 1 Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:21 volumio sudo[28100]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:22:21 volumio go-librespot[28056]: time="2026-01-27T22:22:21+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 22:22:21 volumio sudo[28100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:21 volumio sudo[28100]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:21 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::updateTrackBlock Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrackBlock Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:21 volumio volumio-remote-updater[628]: [2026-01-27 22:22:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769527339 101 Jan 27 22:22:21 volumio volumio[27932]: 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 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:21 volumio volumio[27932]: info: Reloading queue from file Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::setRepeat null single undefined Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::setRandom null Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: Setting Device type: Raspberry PI Jan 27 22:22:21 volumio volumio[27932]: info: Completed loading Core Plugins Jan 27 22:22:21 volumio volumio[27932]: info: Preparing to generate the ALSA configuration file Jan 27 22:22:21 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: Asound.conf file unchanged, so no further update is needed Jan 27 22:22:21 volumio volumio[27932]: info: Output device has changed, restarting MPD Jan 27 22:22:21 volumio volumio[27932]: info: Output device has changed, restarting Shairport Sync Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:21 volumio sudo[28114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 22:22:21 volumio sudo[28114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio sudo[28116]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:22:22 volumio sudo[28116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio sudo[28116]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio sudo[28118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:22:22 volumio sudo[28118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio volumio[27932]: info: ___________ START PLUGINS ___________ Jan 27 22:22:22 volumio volumio[27932]: info: ControllerMpd::onStart: Initializing MPD Jan 27 22:22:22 volumio volumio[27932]: info: Creating MPD Configuration file Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342176] CoreMusicLibrary::Adding element Media Servers Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 22:22:22 volumio sudo[28129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:22:22 volumio sudo[28129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio sudo[28114]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio volumio[27932]: info: UPNP Browser: Client initialized successfully Jan 27 22:22:22 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:22:22 volumio sudo[28127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:22:22 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:22:22 volumio sudo[28127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio systemd[1]: mpd.service: Consumed 7.425s CPU time. Jan 27 22:22:22 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:22:22 volumio sudo[28127]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:22:22 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:22:22 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342634] CoreMusicLibrary::Adding element Last_100 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342653] CoreMusicLibrary::Adding element Webradio Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:22 volumio volumio[27932]: info: Initializing BBC Radios Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio sudo[28137]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 22:22:22 volumio sudo[28137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 22:22:22 volumio sudo[28137]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio volumio[27932]: info: Creating Spotify config file Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:23 volumio volumio[28066]: Starting albumart workers Jan 27 22:22:23 volumio volumio[28065]: Starting albumart workers Jan 27 22:22:24 volumio volumio[28064]: Starting albumart workers Jan 27 22:22:24 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:24 volumio volumio[27932]: info: [1769527344228] CoreMusicLibrary::Adding element YouTube Music Jan 27 22:22:24 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:24 volumio volumio[27932]: Cannot find translation for source YouTube Music Jan 27 22:22:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 27 22:22:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:24 volumio volumio[27932]: info: Volumio Calling Home Jan 27 22:22:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:24 volumio go-librespot[28157]: go-librespot daemon starting... Jan 27 22:22:24 volumio go-librespot[28162]: time="2026-01-27T22:22:24+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:24 volumio sudo[28159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 22:22:24 volumio sudo[28159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:24 volumio sudo[28159]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:25 volumio go-librespot[28162]: time="2026-01-27T22:22:25+07:00" level=info msg="zeroconf server listening on port 38529" Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: Found device Volumio Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:25 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: Found device Volumio Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:25 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:25 volumio volumio[27932]: info: MPD Permissions set Jan 27 22:22:25 volumio volumio[27932]: info: MPD Permissions set Jan 27 22:22:25 volumio volumio[27932]: info: Upmpdcli Daemon Started Jan 27 22:22:25 volumio volumio[27932]: info: Spotify config file written Jan 27 22:22:25 volumio volumio[27932]: 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 22:22:25 volumio volumio[27932]: info: Volumio called home Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio sudo[28172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 22:22:25 volumio sudo[28172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: No need to fix Spotify hosts Jan 27 22:22:25 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 22:22:25 volumio systemd[1]: go-librespot-daemon.service: Killing process 28166 (go-librespot) with signal SIGKILL. Jan 27 22:22:25 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 22:22:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:26 volumio go-librespot[28191]: go-librespot daemon starting... Jan 27 22:22:26 volumio sudo[28172]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=debug msg="app state loaded" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+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 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+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 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+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 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="zeroconf server listening on port 44761" Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: BQCqm4hFtWrs4W0KGpO-E9oh-1smLMCvusowiF5WVbC4IqO1MAxW7cl3D0Fir8A8PsONkrMtGe-bF4-4oxkCse3M6UCTG1dup_r4jfpJ7ufCUCqzoDT_IHDCM4BVJo8_63yyUdPOZR7qLulCbc6bGODxKtLS07u8IneVwhPPSTmIqtESwC0ux4vav8OGAaFWK0-6_i6nMvyl8lYQGTeVo0tawr6AmBFiim2348IbUUSHl4oFfVCDRN7SLTMqTclNpLfR_7GYu913p7O0h3taS0nSHjqA_Zu4o8Yue0TfO5QtvJPT0OxlOICh Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:22:26 volumio volumio[27932]: info: New Spotify access token = BQCqm4hFtWrs4W0KGpO-E9oh-1smLMCvusowiF5WVbC4IqO1MAxW7cl3D0Fir8A8PsONkrMtGe-bF4-4oxkCse3M6UCTG1dup_r4jfpJ7ufCUCqzoDT_IHDCM4BVJo8_63yyUdPOZR7qLulCbc6bGODxKtLS07u8IneVwhPPSTmIqtESwC0ux4vav8OGAaFWK0-6_i6nMvyl8lYQGTeVo0tawr6AmBFiim2348IbUUSHl4oFfVCDRN7SLTMqTclNpLfR_7GYu913p7O0h3taS0nSHjqA_Zu4o8Yue0TfO5QtvJPT0OxlOICh Jan 27 22:22:26 volumio volumio[27932]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+07:00" level=debug msg="obtained new client token: AABGlEupMilQMeFBZaKZs19HOlMVTPPU62nUfiy+WS/JKPifwR0OaAAxdXV02NzbDDcHoSKOjjON1fdm6YV9LaVUDY1Ey41gvzgikehkrdam2+O2jOED+pfO9J0Abm8XyvG+VDO4yp7s9JTWHIFuq7prNPH+DVNKGtV4OatP71/mffgghNBNYTCLOLm34O+JCLVrQZihPNco8nkP1xxccAlFdaaaF2csH3n7x6mZvmOiQyJ45edzUyu9R8s=" Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:27 volumio sudo[28212]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28212]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:27 volumio sudo[28214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio sudo[28214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+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 22:22:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:27 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 22:22:27 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 22:22:27 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:22:27 volumio systemd[1]: shairport-sync.service: Consumed 2.342s CPU time. Jan 27 22:22:27 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:22:27 volumio sudo[28212]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio sudo[28216]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio sudo[28214]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:27 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: Error adding Membership: Error: addMembership EINVAL Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: 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 22:22:27 volumio volumio[27932]: info: Spotify Successfully logged in Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:27 volumio volumio[27932]: info: [1769527347842] CoreMusicLibrary::Adding element Spotify Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:27 volumio volumio[27932]: Cannot find translation for source YouTube Music Jan 27 22:22:27 volumio volumio[27932]: Cannot find translation for source Spotify Jan 27 22:22:28 volumio volumio[27932]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:28 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:28 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:28 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:28 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:29 volumio volumio[27932]: info: go-librespot daemon successfully initialized Jan 27 22:22:30 volumio mpd[28156]: 2026-01-27T22:22:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 22:22:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 22:22:30 volumio sudo[28129]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:30 volumio sudo[28118]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:30 volumio volumio[27932]: error: MPD error: The expression evaluated to a falsy value: Jan 27 22:22:30 volumio volumio[27932]: assert.ok(self.idling) Jan 27 22:22:30 volumio volumio[27932]: error: The expression evaluated to a falsy value: Jan 27 22:22:30 volumio volumio[27932]: assert.ok(self.idling) Jan 27 22:22:30 volumio volumio[27932]: error: updateQueue error: null Jan 27 22:22:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 22:22:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:30 volumio volumio[27932]: info: MPD running with PID28156 Jan 27 22:22:30 volumio volumio[27932]: ,establishing connection Jan 27 22:22:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:30 volumio go-librespot[28255]: go-librespot daemon starting... Jan 27 22:22:30 volumio volumio[27932]: info: Completed starting Core Plugins Jan 27 22:22:30 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:30 volumio volumio[27932]: info: ----- MyVolumio plugins startup ---- Jan 27 22:22:30 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:30 volumio volumio[27932]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=debug msg="app state loaded" Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:30 volumio volumio[27932]: error: updateQueue error: null Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+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 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+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 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+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 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=info msg="zeroconf server listening on port 37619" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="obtained new client token: AABJzjw8GE8bGs6l0sI+tHYzvLlqNUEcuoJUWQQn9CNi4WGSc4aLGMQOAHOFrteEYd5BL6dJRvl6nONJfywUrtbGzDliuZziY+AksmMCPOY3p8zJVc9uk7cWV71CrWMzbSTVjMkLElKym8fG1hORULTgmOeFVlUYNWkEVXI/i+IBUjTRQPQk68MhqHsNPBQb+TtjpB7CH7Rjaf2sr54zCltouUh7hIFOSUFuewi6Zlq7O8r4IYtl3xr9iNU=" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+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 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="completed challenge" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+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 22:22:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:32 volumio volumio[27932]: info: Initializing connection to go-librespot Websocket Jan 27 22:22:32 volumio volumio[27932]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 22:22:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:35 volumio go-librespot[28264]: go-librespot daemon starting... Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="app state loaded" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:35 volumio volumio[27932]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+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 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+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 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+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 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="zeroconf server listening on port 34689" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="obtained new client token: AADmHc5c/DOwcFHhjf3j3n20pRZSoSV4AcFDFytiQLAXDcFyc6Zpn0OymCqmleXTUiG+1KalLDduIgXL9iSKJ4jsm6zNRYWOi0mH5WZyXv8mVQd/Tq6zOhx9RJQCAdctiDK4avihoqpFflYaMKD9PpfWWulx2ENr1XVqbGjHY8lwsRKBpizuFocEz5UEGNm/zf3LWyryXATI1UwX8PE50WreLREY4EvKLfoYHutCotEv7vr8rg7XyuVg8XM=" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:35 volumio volumio[27932]: info: Initializing connection to go-librespot Websocket Jan 27 22:22:36 volumio go-librespot[28265]: time="2026-01-27T22:22:36+07:00" level=debug msg="new websocket client" Jan 27 22:22:36 volumio volumio[27932]: info: Connection to go-librespot Websocket established Jan 27 22:22:36 volumio go-librespot[28265]: time="2026-01-27T22:22: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 22:22:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:36 volumio volumio[27932]: info: Connection to go-librespot Websocket closed Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:39 volumio volumio[27932]: info: Getting Spotify volume Jan 27 22:22:39 volumio volumio[27932]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:22:39 volumio volumio[27932]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:22:39 volumio volumio[27932]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 27 22:22:39 volumio volumio[27932]: errno: -111, Jan 27 22:22:39 volumio volumio[27932]: code: 'ECONNREFUSED', Jan 27 22:22:39 volumio volumio[27932]: syscall: 'connect', Jan 27 22:22:39 volumio volumio[27932]: address: '127.0.0.1', Jan 27 22:22:39 volumio volumio[27932]: port: 9879, Jan 27 22:22:39 volumio volumio[27932]: response: undefined Jan 27 22:22:39 volumio volumio[27932]: } Jan 27 22:22:39 volumio volumio[27932]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 22:22:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:39 volumio go-librespot[28284]: go-librespot daemon starting... Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=debug msg="app state loaded" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+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 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+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 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+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 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="zeroconf server listening on port 40331" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22:40+07:00" level=debug msg="obtained new client token: AAA+sZ52Rh2ZsXQDrYGGY9L0OXHfYGNCrjNqA/U7FD+G07TrujRWP3Z36H2BTOlpKCzJ6zoZ4eBuBT4LLyl4ss4I7ek+mzWgC0RrCWk2D1gsr2loRt2OHzEMQEnhh62ZDYV5u/w4Uwe/WhhHfw5G6fzroeI7LKb260ZIgvz7Wu0bbkkOvZlsrAjR3keAU7Pm/Lxg+EeLYkH8Q7XGrLZMo6kYhdDNiDWGyBKEeE7yQ5YYwvEexI5W1QLr" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22:40+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22: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 22:22:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:40 volumio sudo[28309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:21' Jan 27 22:22:40 volumio sudo[28309]: 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"