Jan 28 14:16:00 volumio volumio[26067]: Starting albumart workers Jan 28 14:16:00 volumio volumio[25939]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:00 volumio volumio[25939]: info: [1769584560381] CoreMusicLibrary::Adding element YouTube Music Jan 28 14:16:00 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:00 volumio volumio[25939]: Cannot find translation for source YouTube Music Jan 28 14:16:00 volumio volumio[26066]: Starting albumart workers Jan 28 14:16:00 volumio volumio[25939]: info: Volumio Calling Home Jan 28 14:16:00 volumio sudo[26172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 28 14:16:00 volumio sudo[26172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:00 volumio go-librespot[26162]: time="2026-01-28T14:16:00+07:00" level=info msg="zeroconf server listening on port 37449" Jan 28 14:16:00 volumio sudo[26172]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:01 volumio volumio[26068]: Starting albumart workers Jan 28 14:16:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:01 volumio volumio[25939]: info: MPD Permissions set Jan 28 14:16:01 volumio volumio[25939]: info: MPD Permissions set Jan 28 14:16:01 volumio volumio[25939]: info: Upmpdcli Daemon Started Jan 28 14:16:01 volumio volumio[25939]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:16:01 volumio volumio[25939]: info: Discovery: Found device Volumio Jan 28 14:16:01 volumio volumio[25939]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:01 volumio volumio[25939]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:01 volumio volumio[25939]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:16:01 volumio volumio[25939]: info: Discovery: Found device Volumio Jan 28 14:16:01 volumio volumio[25939]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:01 volumio volumio[25939]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:01 volumio volumio[25939]: info: Volumio called home Jan 28 14:16:01 volumio volumio[25939]: info: Spotify config file written Jan 28 14:16:01 volumio sudo[26178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 14:16:01 volumio sudo[26178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 14:16:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 14:16:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:01 volumio go-librespot[26180]: go-librespot daemon starting... Jan 28 14:16:01 volumio sudo[26178]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:01 volumio go-librespot[26187]: time="2026-01-28T14:16:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:01 volumio go-librespot[26187]: time="2026-01-28T14:16:01+07:00" level=debug msg="app state loaded" Jan 28 14:16:02 volumio go-librespot[26187]: time="2026-01-28T14:16:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:02 volumio volumio[25939]: 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 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:02 volumio volumio[25939]: info: No need to fix Spotify hosts Jan 28 14:16:02 volumio go-librespot[26187]: time="2026-01-28T14:16:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 14:16:02 volumio go-librespot[26187]: time="2026-01-28T14:16:02+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 28 14:16:02 volumio go-librespot[26187]: time="2026-01-28T14:16:02+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 28 14:16:02 volumio go-librespot[26187]: time="2026-01-28T14:16:02+07:00" level=info msg="zeroconf server listening on port 45831" Jan 28 14:16:03 volumio go-librespot[26187]: time="2026-01-28T14:16:03+07:00" level=debug msg="obtained new client token: AAB93PonLfHSqvewHnUa/4UBEjsCAM4dWP5HP4ciKkgnDPkdI35hDNgkF/5tS/Et45BPe02GJ3fUpRSZMmJy7RyFYBZysNwTX5+Iyp5al3f+Ye5yP9z7P0mM2fJb0Wa7QvXWsoRp1XU6vGl6eguOeUoM9t31appm+cLKnl7umWhIJj9n2nhMDF765MiWhVQkdTvyZYU2PQHXnuSaAmTaw2dviDvef2c86O1y1wQnL8NbppkadWNAg2g5" Jan 28 14:16:03 volumio go-librespot[26187]: time="2026-01-28T14:16:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:03 volumio volumio[25939]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:16:03 volumio volumio[25939]: SPOTIFY: BQCabCrbEtiPgdtW2qYtN56eapi1Cg2DT7PxEaZVJn6P7KMdS6XJ-WnFlgBICXvjgJmgTCcn_Nnfnjvdm-rfxisnCbE_qAFR9aOKnKHjZL9rVEhR-r7_k-ch5Ti8yOxa3r8_9eSosuh6E4h0un9cUu2gfv9PxVlUQ0O452YWT3ci6Wfi0VD9Cxx0n1mx7qveaoaZX9cm5Xig70jDv1wJ_0_Ny75NURZnwPDIJoCZVEhzyg4FB6DRxLQASD4LEABRMpJcqaeqbN77Wx-niLezlIwTl7Q1H5G1N999Udc_zpS0TwEH9WNsQzLs Jan 28 14:16:03 volumio volumio[25939]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:16:03 volumio volumio[25939]: info: New Spotify access token = BQCabCrbEtiPgdtW2qYtN56eapi1Cg2DT7PxEaZVJn6P7KMdS6XJ-WnFlgBICXvjgJmgTCcn_Nnfnjvdm-rfxisnCbE_qAFR9aOKnKHjZL9rVEhR-r7_k-ch5Ti8yOxa3r8_9eSosuh6E4h0un9cUu2gfv9PxVlUQ0O452YWT3ci6Wfi0VD9Cxx0n1mx7qveaoaZX9cm5Xig70jDv1wJ_0_Ny75NURZnwPDIJoCZVEhzyg4FB6DRxLQASD4LEABRMpJcqaeqbN77Wx-niLezlIwTl7Q1H5G1N999Udc_zpS0TwEH9WNsQzLs Jan 28 14:16:03 volumio volumio[25939]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 14:16:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:03 volumio go-librespot[26187]: time="2026-01-28T14:16:03+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:03 volumio go-librespot[26187]: time="2026-01-28T14:16:03+07:00" level=debug msg="completed challenge" Jan 28 14:16:03 volumio volumio[25939]: info: Starting Shairport Sync Jan 28 14:16:03 volumio volumio[25939]: info: Starting Shairport Sync Jan 28 14:16:03 volumio go-librespot[26187]: time="2026-01-28T14:16: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 28 14:16:03 volumio volumio[25939]: info: Starting Shairport Sync Jan 28 14:16:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:03 volumio sudo[26217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:03 volumio sudo[26217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:03 volumio sudo[26221]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:03 volumio sudo[26221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:03 volumio sudo[26219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:03 volumio sudo[26219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:03 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 14:16:03 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 14:16:03 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:03 volumio systemd[1]: shairport-sync.service: Consumed 2.327s CPU time. Jan 28 14:16:03 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:03 volumio sudo[26221]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:03 volumio sudo[26217]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:03 volumio sudo[26219]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:03 volumio volumio[25939]: info: Shairport-Sync Started Jan 28 14:16:03 volumio volumio[25939]: Error adding Membership: Error: addMembership EINVAL Jan 28 14:16:03 volumio volumio[25939]: info: Shairport-Sync Started Jan 28 14:16:03 volumio volumio[25939]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:03 volumio volumio[25939]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:03 volumio volumio[25939]: info: Shairport-Sync Started Jan 28 14:16:04 volumio volumio[25939]: 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 28 14:16:04 volumio volumio[25939]: info: Spotify Successfully logged in Jan 28 14:16:04 volumio volumio[25939]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:04 volumio volumio[25939]: info: [1769584564071] CoreMusicLibrary::Adding element Spotify Jan 28 14:16:04 volumio volumio[25939]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:04 volumio volumio[25939]: Cannot find translation for source YouTube Music Jan 28 14:16:04 volumio volumio[25939]: Cannot find translation for source Spotify Jan 28 14:16:04 volumio volumio[25939]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 28 14:16:04 volumio volumio[25939]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:16:05 volumio volumio[25939]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:16:05 volumio volumio[25939]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:05 volumio volumio[25939]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:05 volumio volumio[25939]: info: CoreStateMachine::pushState Jan 28 14:16:05 volumio volumio[25939]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:05 volumio volumio[25939]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:05 volumio volumio[25939]: info: go-librespot daemon successfully initialized Jan 28 14:16:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 14:16:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:06 volumio go-librespot[26257]: go-librespot daemon starting... Jan 28 14:16:06 volumio go-librespot[26258]: time="2026-01-28T14:16:06+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:06 volumio go-librespot[26258]: time="2026-01-28T14:16:06+07:00" level=debug msg="app state loaded" Jan 28 14:16:06 volumio go-librespot[26258]: time="2026-01-28T14:16:06+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:07 volumio mpd[26163]: 2026-01-28T14:16:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 28 14:16:07 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 28 14:16:07 volumio sudo[26132]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:07 volumio sudo[26121]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16: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-gew4.spotify.com:80]" Jan 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+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 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+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 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+07:00" level=info msg="zeroconf server listening on port 40017" Jan 28 14:16:07 volumio volumio[25939]: error: MPD error: The expression evaluated to a falsy value: Jan 28 14:16:07 volumio volumio[25939]: assert.ok(self.idling) Jan 28 14:16:07 volumio volumio[25939]: error: The expression evaluated to a falsy value: Jan 28 14:16:07 volumio volumio[25939]: assert.ok(self.idling) Jan 28 14:16:07 volumio volumio[25939]: info: Completed starting Core Plugins Jan 28 14:16:07 volumio volumio[25939]: info: ------------------------------------------- Jan 28 14:16:07 volumio volumio[25939]: info: ----- MyVolumio plugins startup ---- Jan 28 14:16:07 volumio volumio[25939]: info: ------------------------------------------- Jan 28 14:16:07 volumio volumio[25939]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 28 14:16:07 volumio volumio[25939]: info: MPD running with PID26163 Jan 28 14:16:07 volumio volumio[25939]: ,establishing connection Jan 28 14:16:07 volumio volumio[25939]: error: updateQueue error: null Jan 28 14:16:07 volumio volumio[25939]: error: updateQueue error: null Jan 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+07:00" level=debug msg="obtained new client token: AACiSb5eAbBJisjVUdpdCWHPOmlMl1yqBz74GqwVe+nDiftkNUuE/szKdQ6zBGYMA0gC0oEne6t2x/CzwqP5yT/iDFWckp1arYAI/NZjDv+JS7QtJN9ffgDid93tTS6I8xk/2ZGr0NK5yNTKVeX2zkb8WA5yH47/UgOgl+cs4MSfj/0v9Vd0xAjtKQ3XS2K+xIp6/xMnRJsJkNbYhHEy/0CRkMAqaa7CjIOHHUu3zKs6VpPjhGLoHlxPJqs=" Jan 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:07 volumio go-librespot[26258]: time="2026-01-28T14:16:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.107:49752->104.199.241.202:4070: read: connection reset by peer" Jan 28 14:16:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:08 volumio volumio[25939]: info: Initializing connection to go-librespot Websocket Jan 28 14:16:08 volumio volumio[25939]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:16:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 28 14:16:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:11 volumio go-librespot[26269]: go-librespot daemon starting... Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=debug msg="app state loaded" Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16: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-gew4.spotify.com:80]" Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+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 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+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 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=info msg="zeroconf server listening on port 37673" Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=debug msg="obtained new client token: AAAeXieeZlYvKquu8GJQ0BKv/vPaTaKSx+1gpgMjMGP4x/PiAq/sPRMZWsN/IOuzTyjRLkSkVh5ewwtR4bCDVNtKhgAZCDSufwDOW5yebiSfTvD2Vjuas2JZVAB0p90KWXVfOT4ijJPaL0ZD2tYfF/ZEB8TejeolkW269lM3XzS9UCOMlu7Ns/daR8pHbULI88MvQAD7V9Nd3lmEtV4RB//2fDIZZ1/o+AeoSe+vphdKWVrCc2RkQwbR3q8=" Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:11 volumio volumio[25939]: info: Initializing connection to go-librespot Websocket Jan 28 14:16:11 volumio go-librespot[26270]: time="2026-01-28T14:16:11+07:00" level=debug msg="new websocket client" Jan 28 14:16:11 volumio volumio[25939]: info: Connection to go-librespot Websocket established Jan 28 14:16:12 volumio go-librespot[26270]: time="2026-01-28T14:16:12+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:12 volumio go-librespot[26270]: time="2026-01-28T14:16:12+07:00" level=debug msg="completed challenge" Jan 28 14:16:12 volumio go-librespot[26270]: time="2026-01-28T14:16: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 28 14:16:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:12 volumio volumio[25939]: info: Connection to go-librespot Websocket closed Jan 28 14:16:12 volumio volumio[25939]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 28 14:16:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:14 volumio volumio[25939]: info: Getting Spotify volume Jan 28 14:16:15 volumio volumio[25939]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:16:15 volumio volumio[25939]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:16:15 volumio volumio[25939]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 28 14:16:15 volumio volumio[25939]: errno: -111, Jan 28 14:16:15 volumio volumio[25939]: code: 'ECONNREFUSED', Jan 28 14:16:15 volumio volumio[25939]: syscall: 'connect', Jan 28 14:16:15 volumio volumio[25939]: address: '127.0.0.1', Jan 28 14:16:15 volumio volumio[25939]: port: 9879, Jan 28 14:16:15 volumio volumio[25939]: response: undefined Jan 28 14:16:15 volumio volumio[25939]: } Jan 28 14:16:15 volumio volumio[25939]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:16:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 28 14:16:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:15 volumio go-librespot[26290]: go-librespot daemon starting... Jan 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+07:00" level=debug msg="app state loaded" Jan 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+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 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+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 28 14:16:15 volumio go-librespot[26291]: time="2026-01-28T14:16:15+07:00" level=info msg="zeroconf server listening on port 38389" Jan 28 14:16:16 volumio go-librespot[26291]: time="2026-01-28T14:16:16+07:00" level=debug msg="obtained new client token: AADwcSAf8Xw7+i+KLDhw/o8WrJVDRIEPGoLLzBsY4KtHmM6G/bWky6Cmax9rXmX86k5W0hdrGM5cbiocuE7UEE5xlzFidFW/l/O4x4tayqsavCWIjd5l653DrH1v7VxQtaQ/3wAs0dE/MvbhSXzh5CPU4n9LXL+KhMWxckJ80s3phDP3AcheTGJbacuEW2ghUGZAIAdPmn0HN6dF3RPC8yF/bSY3rJPSelTCGZwBXc+nuR/ua8Wh3KvT" Jan 28 14:16:16 volumio go-librespot[26291]: time="2026-01-28T14:16:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:16 volumio go-librespot[26291]: time="2026-01-28T14:16:16+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:16 volumio go-librespot[26291]: time="2026-01-28T14:16:16+07:00" level=debug msg="completed challenge" Jan 28 14:16:16 volumio go-librespot[26291]: time="2026-01-28T14:16: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 28 14:16:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:16 volumio sudo[26314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 14:15' Jan 28 14:16:16 volumio sudo[26314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:16 volumio sudo[26314]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:18 volumio volumio-remote-updater[628]: [2026-01-28 14:16:18] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 28 14:16:18 volumio volumio-remote-updater[628]: [2026-01-28 14:16:18] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 28 14:16:18 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:18 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 28 14:16:18 volumio systemd[1]: volumio.service: Consumed 53.097s CPU time. Jan 28 14:16:18 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 14:16:18 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 14:16:18 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10238. Jan 28 14:16:18 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 14:16:18 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 28 14:16:18 volumio systemd[1]: volumio.service: Consumed 53.097s CPU time. Jan 28 14:16:18 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 28 14:16:18 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 14:16:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 28 14:16:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:19 volumio go-librespot[26346]: go-librespot daemon starting... Jan 28 14:16:19 volumio go-librespot[26347]: time="2026-01-28T14:16:19+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:19 volumio go-librespot[26347]: time="2026-01-28T14:16:19+07:00" level=debug msg="app state loaded" Jan 28 14:16:19 volumio go-librespot[26347]: time="2026-01-28T14:16:19+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16: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 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16: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 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16: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 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+07:00" level=info msg="zeroconf server listening on port 40751" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+07:00" level=debug msg="obtained new client token: AAB+SFSjNIJAafQRvybynPvsY59j0osCXQBlc0q7+Q3vXEc5W/rX8JWVvXp1RyeFJzqyDaFbR7IR+5Gg644UmIsxXBJNvvXJtdYxqnQ3BFaiqVZiT+CykuiqezTx83mgJTSz4L54Bb+bSnEZFXNP4HIWTEfosRjt/93v6NfQGqyOCKdH7YtqecBVBvMCOn+nPp6aI+6ucH+QvjQK6UsLVAZ4xWWR9dRU7QN5UIBaWiH25T5+1g6U7dTqhyo=" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+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 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+07:00" level=debug msg="completed challenge" Jan 28 14:16:20 volumio go-librespot[26347]: time="2026-01-28T14:16:20+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 28 14:16:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:22 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:22 volumio volumio[26331]: info: ----- Volumio3 ---- Jan 28 14:16:22 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:22 volumio volumio[26331]: info: ----- System startup ---- Jan 28 14:16:22 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:23 volumio volumio-remote-updater[628]: [2026-01-28 14:16:23] [connect] Successful connection Jan 28 14:16:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:23 volumio volumio[26331]: info: MYVOLUMIO Environment detected Jan 28 14:16:23 volumio volumio[26331]: info: Plugin folders cleanup Jan 28 14:16:23 volumio volumio[26331]: info: Scanning into folder /volumio/app/plugins/ Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category audio_interface Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category miscellanea Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category music_service Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category plugins.json Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category system_controller Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category user_interface Jan 28 14:16:23 volumio volumio[26331]: info: Scanning into folder /data/plugins/ Jan 28 14:16:23 volumio volumio[26331]: info: Scanning category music_service Jan 28 14:16:23 volumio volumio[26331]: info: Plugin folders cleanup completed Jan 28 14:16:23 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:23 volumio volumio[26331]: info: ----- Core plugins startup ---- Jan 28 14:16:23 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:23 volumio volumio[26331]: info: Loading plugins from folder /volumio/app/plugins/ Jan 28 14:16:23 volumio volumio[26331]: info: Adding plugin upnp to MyMusic Plugins Jan 28 14:16:23 volumio volumio[26331]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 28 14:16:23 volumio volumio[26331]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 28 14:16:23 volumio volumio[26331]: info: Loading plugins from folder /data/plugins/ Jan 28 14:16:23 volumio volumio[26331]: info: Loading plugin "system"... Jan 28 14:16:23 volumio volumio[26331]: info: Loading plugin "appearance"... Jan 28 14:16:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 28 14:16:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:24 volumio go-librespot[26366]: go-librespot daemon starting... Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=debug msg="app state loaded" Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+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 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+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 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=info msg="zeroconf server listening on port 43479" Jan 28 14:16:24 volumio go-librespot[26367]: time="2026-01-28T14:16:24+07:00" level=debug msg="obtained new client token: AAAOcHSQnbE99FOqmz4FTxZC2MBrCeXk6R6TZy9QeJL+d0/IY7FIkztu7JzsJ5zVBvgbcrmYSubDlk3PVIQL1IQ7WjqVSKBincBGJfgQ6Aafo9g8+HPnANEIfYI54mTZxWdwVGy0auVqAo6BR1Zzi+L2WzLRwnX1ckmXzuzQz3zt83v0qjXrItKkMKt1Ogwx4787PZku7ET+ZhfVe/YrxvGL+t+/90yIqsdBPeZWA+EV2CWuqoG4USN8iko=" Jan 28 14:16:25 volumio go-librespot[26367]: time="2026-01-28T14:16:25+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:25 volumio go-librespot[26367]: time="2026-01-28T14:16:25+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:25 volumio go-librespot[26367]: time="2026-01-28T14:16:25+07:00" level=debug msg="completed challenge" Jan 28 14:16:25 volumio go-librespot[26367]: time="2026-01-28T14:16:25+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 28 14:16:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:25 volumio volumio[26331]: info: Loading plugin "network"... Jan 28 14:16:25 volumio volumio[26331]: info: Refreshing Cached IP Addresses Jan 28 14:16:25 volumio sudo[26375]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 14:16:25 volumio sudo[26375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:25 volumio sudo[26377]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 14:16:25 volumio sudo[26377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:25 volumio sudo[26377]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:25 volumio volumio[26331]: info: Loading plugin "services"... Jan 28 14:16:25 volumio sudo[26375]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:25 volumio volumio[26331]: info: Loading plugin "alsa_controller"... Jan 28 14:16:25 volumio sudo[26385]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 28 14:16:25 volumio sudo[26385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:26 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "wizard"... Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "networkfs"... Jan 28 14:16:26 volumio volumio[26331]: info: Starting Udev Watcher for removable devices Jan 28 14:16:26 volumio volumio[26331]: info: Ignoring mount for partition: boot Jan 28 14:16:26 volumio volumio[26331]: info: Ignoring mount for partition: volumio Jan 28 14:16:26 volumio volumio[26331]: info: Ignoring mount for partition: volumio_data Jan 28 14:16:26 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "volumio_command_line_client"... Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "upnp"... Jan 28 14:16:26 volumio volumio[26331]: info: [1769584586161] Starting Upmpd Daemon Jan 28 14:16:26 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "my_music"... Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "mpd"... Jan 28 14:16:26 volumio volumio[26331]: info: Loading plugin "upnp_browser"... Jan 28 14:16:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 28 14:16:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:28 volumio go-librespot[26408]: go-librespot daemon starting... Jan 28 14:16:28 volumio sudo[26385]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:28 volumio go-librespot[26409]: time="2026-01-28T14:16:28+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:28 volumio go-librespot[26409]: time="2026-01-28T14:16:28+07:00" level=debug msg="app state loaded" Jan 28 14:16:28 volumio go-librespot[26409]: time="2026-01-28T14:16:28+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+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 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+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 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+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 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=info msg="zeroconf server listening on port 45473" Jan 28 14:16:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=debug msg="obtained new client token: AAAf+1IOwAxq+XXsEOuJ/w7jggtHVdnVDxN/7Emp0K1tAQdeK6itM56hdpRfGmQCwiZFZUTKvXXu7rErNMQlPOExLsS4vYSkJTDzHLWdBS3bE2ZUapFTbBQEtubKxfNg8Cxhw0zZ6nfz+yai3TmYZVH53dryzJsuUq3sK4y4AM8auMVfYf6/Ajx7JoqVGy7dlrtbm+j0u2zXDFClGmw9YpRBNBrD6IR3pK8i6qHjj8OQP7XB8RVLrD5Xpfs=" Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=debug msg="completed challenge" Jan 28 14:16:29 volumio go-librespot[26409]: time="2026-01-28T14:16:29+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 14:16:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:29 volumio volumio[26331]: info: Starting UPNP Browser Jan 28 14:16:29 volumio volumio[26331]: info: Loading plugin "alarm-clock"... Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "airplay_emulation"... Jan 28 14:16:30 volumio volumio[26331]: info: Starting Shairport Sync Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "last_100"... Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "webradio"... Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "i2s_dacs"... Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "volumiodiscovery"... Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** For more information see Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:16:30 volumio volumio[26331]: *** WARNING *** For more information see Jan 28 14:16:30 volumio node[26331]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 14:16:30 volumio node[26331]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:16:30 volumio node[26331]: *** WARNING *** For more information see Jan 28 14:16:30 volumio node[26331]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 14:16:30 volumio node[26331]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:16:30 volumio node[26331]: *** WARNING *** For more information see Jan 28 14:16:30 volumio volumio[26331]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 28 14:16:30 volumio volumio[26331]: info: Discovery: Started advertising with name: Volumio Jan 28 14:16:30 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:16:30 volumio volumio[26331]: info: Loading plugin "spop"... Jan 28 14:16:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:32 volumio volumio[26331]: info: Loading plugin "ytcr"... Jan 28 14:16:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 28 14:16:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:32 volumio go-librespot[26418]: go-librespot daemon starting... Jan 28 14:16:32 volumio go-librespot[26419]: time="2026-01-28T14:16:32+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:32 volumio go-librespot[26419]: time="2026-01-28T14:16:32+07:00" level=debug msg="app state loaded" Jan 28 14:16:32 volumio go-librespot[26419]: time="2026-01-28T14:16:32+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+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 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+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 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+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 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+07:00" level=info msg="zeroconf server listening on port 45115" Jan 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+07:00" level=debug msg="obtained new client token: AACJnHSpqv3f5XDUZ1TfI5jN+wFZXtzPkKW2YqeqbDla5/nhjcBQ5/uaRckdepegqJmhU4IXqdwisZIJim/ZaJuqjWdLGBfkPkdANaqEtmCiMM0Q5QjzGe5ZdSEumEjdWP0VFpT9fFMubpHGt/E6jCgfFTqh1pQIFYj4oyHIYALspg1S74vN4JRZWqO4MixQP83S1AxCwcwQDwbY1RSu7CAubaPe+rmvG7XW05tXf5yOdu9wzNGgzXcdybo=" Jan 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:33 volumio go-librespot[26419]: time="2026-01-28T14:16:33+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 28 14:16:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:35 volumio volumio[26331]: info: Loading plugin "ytmusic"... Jan 28 14:16:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:35 volumio volumio-remote-updater[628]: [2026-01-28 14:16:35] [connect] Successful connection Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "outputs"... Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "albumart"... Jan 28 14:16:36 volumio volumio[26331]: info: Plugin example_plugin is not enabled Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "inputs"... Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "updater_comm"... Jan 28 14:16:36 volumio volumio[26331]: info: Plugin mpdemulation is not enabled Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "rest_api"... Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "websocket"... Jan 28 14:16:36 volumio volumio[26331]: info: Starting Socket.io Server version 1.7.4 Jan 28 14:16:36 volumio volumio[26331]: info: Loading plugin "RoonBridge"... Jan 28 14:16:36 volumio volumio[26331]: info: Applying required configuration parameters for plugin RoonBridge Jan 28 14:16:36 volumio volumio[26331]: info: Loading i18n strings for locale en Jan 28 14:16:36 volumio volumio[26331]: Updating browse sources language Jan 28 14:16:36 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 28 14:16:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:37 volumio go-librespot[26453]: go-librespot daemon starting... Jan 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+07:00" level=debug msg="app state loaded" Jan 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::initPlayerControls Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:16:37 volumio volumio[26331]: Express server listening on port 3000 Jan 28 14:16:37 volumio volumio[26331]: [Metrics] WebUI: 15s 971.82ms Jan 28 14:16:37 volumio volumio[26443]: Forking 3 albumart workers Jan 28 14:16:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:37 volumio volumio[26331]: info: CoreStateMachine::resetVolumioState Jan 28 14:16:37 volumio volumio[26331]: info: CoreStateMachine::getcurrentVolume Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:16:37 volumio sudo[26485]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 14:16:37 volumio sudo[26485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:37 volumio sudo[26485]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:37 volumio sudo[26494]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 14:16:37 volumio sudo[26494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:37 volumio volumio[26331]: info: Volumio Network Manager: Network status updated: 1 Jan 28 14:16:37 volumio sudo[26494]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:37 volumio volumio[26331]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+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 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+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 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+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 28 14:16:37 volumio volumio[26331]: info: CoreStateMachine::pushState Jan 28 14:16:37 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:37 volumio volumio[26331]: info: CoreStateMachine::updateTrackBlock Jan 28 14:16:37 volumio volumio[26331]: info: CorePlayQueue::getTrackBlock Jan 28 14:16:37 volumio volumio[26331]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:16:37 volumio go-librespot[26454]: time="2026-01-28T14:16:37+07:00" level=info msg="zeroconf server listening on port 34019" Jan 28 14:16:37 volumio volumio-remote-updater[628]: [2026-01-28 14:16:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769584595 101 Jan 28 14:16:38 volumio volumio[26331]: 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 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:38 volumio volumio[26331]: info: Reloading queue from file Jan 28 14:16:38 volumio volumio[26331]: info: CoreStateMachine::setRepeat null single undefined Jan 28 14:16:38 volumio volumio[26331]: info: CoreStateMachine::pushState Jan 28 14:16:38 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:38 volumio go-librespot[26454]: time="2026-01-28T14:16:38+07:00" level=debug msg="obtained new client token: AABk8w0dHB5Hnj1WLBTQ8j+BlgUDhE8N7dwlwnU0eQrFY9wL7Af9BPBHvCsLhVSO00EAZ4rgsrPevFcEJdpcPM7ZKbZyohe6SZbgZQZQpTMCH5yD/maedSb2HxbEMH21V9XrieSJXXyfhjNihyMqvS40JSeHm5Kq7h3/HdaBPE3hJ59W5Hpig/H/Yes25oRBT9cet1UM7YwmWbbLIUBoFK0aQEF+BI94YRi+5cd4pGQWa/FgDx+uTpVI" Jan 28 14:16:38 volumio volumio[26331]: info: CoreStateMachine::setRandom null Jan 28 14:16:38 volumio volumio[26331]: info: CoreStateMachine::pushState Jan 28 14:16:38 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:38 volumio volumio[26331]: info: Setting Device type: Raspberry PI Jan 28 14:16:38 volumio volumio[26331]: info: Completed loading Core Plugins Jan 28 14:16:38 volumio volumio[26331]: info: Preparing to generate the ALSA configuration file Jan 28 14:16:38 volumio go-librespot[26454]: time="2026-01-28T14:16:38+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:38 volumio volumio[26331]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:16:38 volumio volumio[26331]: info: CoreStateMachine::pushState Jan 28 14:16:38 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:38 volumio volumio[26331]: info: Asound.conf file unchanged, so no further update is needed Jan 28 14:16:38 volumio volumio[26331]: info: Output device has changed, restarting MPD Jan 28 14:16:38 volumio volumio[26331]: info: Output device has changed, restarting Shairport Sync Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:38 volumio sudo[26512]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 28 14:16:38 volumio sudo[26512]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:38 volumio volumio[26331]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:16:38 volumio volumio[26331]: info: ___________ START PLUGINS ___________ Jan 28 14:16:38 volumio sudo[26514]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 14:16:38 volumio volumio[26331]: info: ControllerMpd::onStart: Initializing MPD Jan 28 14:16:38 volumio volumio[26331]: info: Creating MPD Configuration file Jan 28 14:16:38 volumio sudo[26514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:38 volumio sudo[26517]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 14:16:38 volumio sudo[26517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:38 volumio sudo[26514]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:38 volumio volumio[26331]: info: [1769584598590] CoreMusicLibrary::Adding element Media Servers Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:38 volumio sudo[26524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 14:16:38 volumio sudo[26524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:38 volumio volumio[26331]: info: UPNP Browser: Client initialized successfully Jan 28 14:16:38 volumio sudo[26512]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:38 volumio sudo[26524]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:38 volumio sudo[26527]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 14:16:38 volumio sudo[26527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:38 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 28 14:16:38 volumio volumio[26331]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:38 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 14:16:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 14:16:38 volumio systemd[1]: mpd.service: Consumed 7.423s CPU time. Jan 28 14:16:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 14:16:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 14:16:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 14:16:38 volumio volumio[26331]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:38 volumio volumio[26331]: info: [1769584598879] CoreMusicLibrary::Adding element Last_100 Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:38 volumio volumio[26331]: info: [1769584598889] CoreMusicLibrary::Adding element Webradio Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:38 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:16:38 volumio volumio[26331]: info: Initializing BBC Radios Jan 28 14:16:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 14:16:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 14:16:39 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:16:39 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:39 volumio volumio[26331]: info: Creating Spotify config file Jan 28 14:16:39 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:39 volumio sudo[26542]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 28 14:16:39 volumio sudo[26542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 28 14:16:39 volumio sudo[26542]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:40 volumio volumio[26331]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:40 volumio volumio[26331]: info: [1769584600396] CoreMusicLibrary::Adding element YouTube Music Jan 28 14:16:40 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:40 volumio volumio[26331]: Cannot find translation for source YouTube Music Jan 28 14:16:40 volumio volumio[26331]: info: Volumio Calling Home Jan 28 14:16:40 volumio sudo[26556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 28 14:16:40 volumio sudo[26556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:40 volumio sudo[26556]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:40 volumio volumio[26462]: Starting albumart workers Jan 28 14:16:40 volumio volumio[26466]: Starting albumart workers Jan 28 14:16:41 volumio volumio[26465]: Starting albumart workers Jan 28 14:16:41 volumio volumio[26331]: info: MPD Permissions set Jan 28 14:16:41 volumio volumio[26331]: info: MPD Permissions set Jan 28 14:16:41 volumio volumio[26331]: info: Upmpdcli Daemon Started Jan 28 14:16:41 volumio volumio[26331]: info: Spotify config file written Jan 28 14:16:41 volumio sudo[26563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 14:16:41 volumio sudo[26563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:41 volumio volumio[26331]: 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 28 14:16:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 14:16:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio go-librespot[26567]: go-librespot daemon starting... Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio sudo[26563]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:16:41 volumio volumio[26331]: info: No need to fix Spotify hosts Jan 28 14:16:41 volumio go-librespot[26571]: time="2026-01-28T14:16:41+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:41 volumio go-librespot[26571]: time="2026-01-28T14:16:41+07:00" level=debug msg="app state loaded" Jan 28 14:16:41 volumio go-librespot[26571]: time="2026-01-28T14:16:41+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+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 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+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 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+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 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+07:00" level=info msg="zeroconf server listening on port 39443" Jan 28 14:16:42 volumio volumio[26331]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:16:42 volumio volumio[26331]: info: Discovery: Found device Volumio Jan 28 14:16:42 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:42 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:42 volumio volumio[26331]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:16:42 volumio volumio[26331]: info: Discovery: Found device Volumio Jan 28 14:16:42 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:42 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+07:00" level=debug msg="obtained new client token: AADbi/9yoIKvE2W7pHPdQS3L1yIX3c5BBwCasyPPKW4k32fu5igjrNDybmQWQfijqCVeQBY923Rn0i7h8fGf1CJf+8jjso1AzwtDDu194iUtc3eSHrsog6MvWydICYIrH/MDn2aN4A1y8ZH647Dm2K8AdfK5K/UPjaGm8n2QS53HOFcLydWNOZ9VEUcLEcWGpJ/8VTZkkfJRtwBbnLz66BlYHsGKjooE/kUaCTFDX5ktXKhOh4pqXwh16I0=" Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:42 volumio volumio[26331]: info: Volumio called home Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+07:00" level=debug msg="completed challenge" Jan 28 14:16:42 volumio go-librespot[26571]: time="2026-01-28T14:16:42+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 28 14:16:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:43 volumio volumio[26331]: info: Starting Shairport Sync Jan 28 14:16:43 volumio volumio[26331]: info: Starting Shairport Sync Jan 28 14:16:43 volumio volumio[26331]: info: Starting Shairport Sync Jan 28 14:16:43 volumio volumio[26331]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:16:43 volumio volumio[26331]: SPOTIFY: BQAm7UdMbep3QLSdcLI9TebVxnymu57cFHjIWc6n_A2Bx1EVecdnb3X9_PA-x1ZMOGJoIyfmxg5pC1HtV3Rn2kiS3W5o2HK08yU4lnl9yYLiDBBXxbhJd9djMiDRB-VkrFA8BcViD8oLqj7oyNneGYksTwhpJfY2cjBA_AywuJned6HWKs86vY1MQdb9sI7Cmmffrv8EJC5EoSzLIulcpT8wqO6IBbPme04gP2Xswpu8T0MlCH4ItvgscMLUZFd1AZIYfzuwrGGx6XTrzXeMM2dy7utbvcQpVVSswHzorR-6jP5Rk-jUDPvg Jan 28 14:16:43 volumio volumio[26331]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:16:43 volumio volumio[26331]: info: New Spotify access token = BQAm7UdMbep3QLSdcLI9TebVxnymu57cFHjIWc6n_A2Bx1EVecdnb3X9_PA-x1ZMOGJoIyfmxg5pC1HtV3Rn2kiS3W5o2HK08yU4lnl9yYLiDBBXxbhJd9djMiDRB-VkrFA8BcViD8oLqj7oyNneGYksTwhpJfY2cjBA_AywuJned6HWKs86vY1MQdb9sI7Cmmffrv8EJC5EoSzLIulcpT8wqO6IBbPme04gP2Xswpu8T0MlCH4ItvgscMLUZFd1AZIYfzuwrGGx6XTrzXeMM2dy7utbvcQpVVSswHzorR-6jP5Rk-jUDPvg Jan 28 14:16:43 volumio volumio[26331]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 14:16:43 volumio sudo[26604]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:43 volumio sudo[26604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:43 volumio sudo[26607]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:43 volumio sudo[26607]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:43 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 14:16:43 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 14:16:43 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:43 volumio systemd[1]: shairport-sync.service: Consumed 2.296s CPU time. Jan 28 14:16:43 volumio sudo[26608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:16:43 volumio sudo[26608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:43 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:43 volumio sudo[26604]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:43 volumio volumio[26331]: info: Shairport-Sync Started Jan 28 14:16:43 volumio volumio[26331]: Error adding Membership: Error: addMembership EINVAL Jan 28 14:16:43 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 14:16:43 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 14:16:43 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:43 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:43 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:44 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:16:44 volumio sudo[26607]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:44 volumio sudo[26608]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:44 volumio volumio[26331]: info: Shairport-Sync Started Jan 28 14:16:44 volumio volumio[26331]: info: Shairport-Sync Started Jan 28 14:16:44 volumio volumio[26331]: 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 28 14:16:44 volumio volumio[26331]: info: Spotify Successfully logged in Jan 28 14:16:44 volumio volumio[26331]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:16:44 volumio volumio[26331]: info: [1769584604298] CoreMusicLibrary::Adding element Spotify Jan 28 14:16:44 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:16:44 volumio volumio[26331]: Cannot find translation for source YouTube Music Jan 28 14:16:44 volumio volumio[26331]: Cannot find translation for source Spotify Jan 28 14:16:44 volumio volumio[26331]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 28 14:16:44 volumio volumio[26331]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:16:45 volumio volumio[26331]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:16:45 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:16:45 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:45 volumio volumio[26331]: info: CoreStateMachine::pushState Jan 28 14:16:45 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:16:45 volumio volumio[26331]: info: CoreCommandRouter::volumioPushState Jan 28 14:16:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 14:16:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:46 volumio go-librespot[26646]: go-librespot daemon starting... Jan 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+07:00" level=debug msg="app state loaded" Jan 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:46 volumio volumio[26331]: info: go-librespot daemon successfully initialized Jan 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16: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-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+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 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+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 28 14:16:46 volumio go-librespot[26656]: time="2026-01-28T14:16:46+07:00" level=info msg="zeroconf server listening on port 35411" Jan 28 14:16:46 volumio mpd[26554]: 2026-01-28T14:16:46 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 28 14:16:46 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 28 14:16:46 volumio sudo[26517]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:46 volumio sudo[26527]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:47 volumio go-librespot[26656]: time="2026-01-28T14:16:47+07:00" level=debug msg="obtained new client token: AAAslcANyIX1cBFmrt13txpNCLuAA9ZS/9PzYki+S3cmOxUInTqL+i+bb0XtLTIrIwFR0nsVp8O9+tDTzW/mXr9HbO/SSjYIKl7oYfVcByGOtIYfHUzc5330UgW6PCoREe5BuqpFcetkUxPr7V6HFhyERcaC4I8/2ZnMVlAxmDskne1zQtSrjDOl7vAuqO7jd6i9UIBKtBEaDIQhhwPUFjkMuRrffBDpnTSvzIfE0fdYN8j9rJbVDQx+" Jan 28 14:16:47 volumio volumio[26331]: error: MPD error: The expression evaluated to a falsy value: Jan 28 14:16:47 volumio volumio[26331]: assert.ok(self.idling) Jan 28 14:16:47 volumio volumio[26331]: error: The expression evaluated to a falsy value: Jan 28 14:16:47 volumio volumio[26331]: assert.ok(self.idling) Jan 28 14:16:47 volumio volumio[26331]: error: updateQueue error: null Jan 28 14:16:47 volumio volumio[26331]: info: MPD running with PID26554 Jan 28 14:16:47 volumio volumio[26331]: ,establishing connection Jan 28 14:16:47 volumio go-librespot[26656]: time="2026-01-28T14:16:47+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:47 volumio volumio[26331]: info: Completed starting Core Plugins Jan 28 14:16:47 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:47 volumio volumio[26331]: info: ----- MyVolumio plugins startup ---- Jan 28 14:16:47 volumio volumio[26331]: info: ------------------------------------------- Jan 28 14:16:47 volumio volumio[26331]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 28 14:16:47 volumio volumio[26331]: error: updateQueue error: null Jan 28 14:16:47 volumio go-librespot[26656]: time="2026-01-28T14:16:47+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:47 volumio go-librespot[26656]: time="2026-01-28T14:16:47+07:00" level=debug msg="completed challenge" Jan 28 14:16:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:47 volumio go-librespot[26656]: time="2026-01-28T14:16:47+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 28 14:16:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:49 volumio volumio[26331]: info: Initializing connection to go-librespot Websocket Jan 28 14:16:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:49 volumio volumio[26331]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:16:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 28 14:16:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:50 volumio go-librespot[26670]: go-librespot daemon starting... Jan 28 14:16:50 volumio go-librespot[26671]: time="2026-01-28T14:16:50+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:50 volumio go-librespot[26671]: time="2026-01-28T14:16:50+07:00" level=debug msg="app state loaded" Jan 28 14:16:50 volumio go-librespot[26671]: time="2026-01-28T14:16:50+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+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 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+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 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+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 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+07:00" level=info msg="zeroconf server listening on port 44663" Jan 28 14:16:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+07:00" level=debug msg="obtained new client token: AADHua98acOo6SoC/LniKEPZIUcKlmWGp91ermkXs6bQ4tD5mv0d/YnG7w98esVlJwAgW8oMylJt37lHMA/hPH1MouJjnkng381jltHyqbkbWg3njQ8R8rFjuxTtAcUWkZwmrfxygt8pAutEzEZfaDEA+OFzi7L6kPLg1BdMxMPeKsFL0XXwlGoBDMoaSz7h5SNojQ6bFuetLNy7M4I+72nk2GxNkbO/N+6QB/7f3cpa63yYysuyMbhBMko=" Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16:51+07:00" level=debug msg="completed challenge" Jan 28 14:16:51 volumio go-librespot[26671]: time="2026-01-28T14:16: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 28 14:16:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:51 volumio volumio[26331]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 28 14:16:52 volumio volumio[26331]: info: Initializing connection to go-librespot Websocket Jan 28 14:16:52 volumio volumio[26331]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:16:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 28 14:16:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:54 volumio go-librespot[26678]: go-librespot daemon starting... Jan 28 14:16:54 volumio go-librespot[26679]: time="2026-01-28T14:16:54+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:54 volumio go-librespot[26679]: time="2026-01-28T14:16:54+07:00" level=debug msg="app state loaded" Jan 28 14:16:54 volumio go-librespot[26679]: time="2026-01-28T14:16:54+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+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 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+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 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+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 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=info msg="zeroconf server listening on port 41477" Jan 28 14:16:55 volumio volumio[26331]: info: Initializing connection to go-librespot Websocket Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=debug msg="new websocket client" Jan 28 14:16:55 volumio volumio[26331]: info: Connection to go-librespot Websocket established Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=debug msg="obtained new client token: AAC+4JtkEYN5KmIJxy535rMeg1MScxvcFaw+q4efExfs2RLzVsY2WT2BHChSorkZzo8btPZT4LwK2r+LcT/4hOcWghKaYIL1zbTrRMRqWVVEEsh0yEFmC3Xx6S9Gybt+RKoTwMAQBQLQf0tcKeeAh6J/428Wf7TwraCTnjOGVH8TKoyvJtHrQ/SkCwZT0n74Z/cVSyKMVyPvfG3jMRVe0B363LVHnS275GWx9FrjwPai9V87zb4YK/GKek8=" Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=debug msg="completed keyexchange" Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16:55+07:00" level=debug msg="completed challenge" Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin bluetooth to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin multiroom to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin metavolumio to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin cd_controller to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 28 14:16:55 volumio volumio[26331]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 28 14:16:55 volumio go-librespot[26679]: time="2026-01-28T14:16: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 28 14:16:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:16:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:16:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:57 volumio volumio[26331]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 28 14:16:57 volumio volumio[26331]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 28 14:16:57 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:57 volumio volumio[26331]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:16:57 volumio volumio[26331]: info: Starting MyVolumio Remote Streaming Endpoints Jan 28 14:16:57 volumio volumio[26331]: info: MyVolumio login type: Token Jan 28 14:16:58 volumio volumio[26331]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 28 14:16:58 volumio volumio[26331]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 28 14:16:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 28 14:16:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:16:59 volumio go-librespot[26701]: go-librespot daemon starting... Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16:59+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16:59+07:00" level=debug msg="app state loaded" Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16:59+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:16:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:16:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:16:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16: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 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16: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 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16: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 28 14:16:59 volumio volumio[26331]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 28 14:16:59 volumio volumio[26331]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16:59+07:00" level=info msg="zeroconf server listening on port 33859" Jan 28 14:16:59 volumio volumio[26331]: info: Streaming services startup Jan 28 14:16:59 volumio volumio[26331]: info: Starting Streaming Daemon Jan 28 14:16:59 volumio sudo[26710]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 28 14:16:59 volumio sudo[26710]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:16:59 volumio volumio[26331]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 28 14:16:59 volumio sudo[26710]: pam_unix(sudo:session): session closed for user root Jan 28 14:16:59 volumio volumio[26331]: info: Getting Spotify volume Jan 28 14:16:59 volumio go-librespot[26702]: time="2026-01-28T14:16:59+07:00" level=debug msg="obtained new client token: AACVyvXiGMzhukjQivC0YA5h4QpdCLRO4OcalcntNC+Lhn5Bvbq2RKH+fYMwjnTj4/Is0nSWo71wUkkg1f/0/Vojplw/LJAymwO9nKht5qzBqO+G6n4pvbnRBJgxe7K+cOduI0NsXL2ZVCFVSOX+uf0jmLm4Y8spvXM5v7qLSmrghTHssu50As7DRaKHYQFL0SICIuMzZTK2wv5bNDjXGh2D0DUAVevq6FcORGM16F997Dw4RZKpCjHJvNM=" Jan 28 14:16:59 volumio volumio[26331]: info: Connection to go-librespot Websocket closed Jan 28 14:16:59 volumio volumio[26331]: error: Cannot start Volumio Streaming Daemon Jan 28 14:16:59 volumio volumio[26331]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 28 14:16:59 volumio volumio[26331]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 28 14:16:59 volumio volumio[26331]: 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 28 14:17:00 volumio go-librespot[26702]: time="2026-01-28T14:17:00+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:00 volumio go-librespot[26702]: time="2026-01-28T14:17:00+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:00 volumio go-librespot[26702]: time="2026-01-28T14:17:00+07:00" level=debug msg="completed challenge" Jan 28 14:17:00 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:00 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:00 volumio volumio[26331]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 28 14:17:00 volumio volumio[26331]: SPOTIFY: SPOTIFY VOLUME undefined Jan 28 14:17:00 volumio volumio[26331]: SPOTIFY: VOLUMIO VOLUME 100 Jan 28 14:17:00 volumio volumio[26331]: info: Aligning Spotify Volume to Volumio Volume Jan 28 14:17:00 volumio volumio[26331]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:00 volumio volumio[26331]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:00 volumio volumio[26331]: info: Setting Spotify Volume from Volumio: 100 Jan 28 14:17:00 volumio go-librespot[26702]: time="2026-01-28T14:17:00+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 28 14:17:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:00 volumio volumio[26331]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:17:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:00 volumio volumio[26331]: Error: socket hang up Jan 28 14:17:00 volumio volumio[26331]: at connResetException (node:internal/errors:720:14) Jan 28 14:17:00 volumio volumio[26331]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 28 14:17:00 volumio volumio[26331]: at Socket.emit (node:events:526:35) Jan 28 14:17:00 volumio volumio[26331]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 28 14:17:00 volumio volumio[26331]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 28 14:17:00 volumio volumio[26331]: code: 'ECONNRESET', Jan 28 14:17:00 volumio volumio[26331]: response: undefined Jan 28 14:17:00 volumio volumio[26331]: } Jan 28 14:17:00 volumio volumio[26331]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:17:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:01 volumio sudo[26730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 14:16' Jan 28 14:17:01 volumio sudo[26730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:01 volumio sudo[26730]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 28 14:17:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:03 volumio go-librespot[26738]: go-librespot daemon starting... Jan 28 14:17:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:03 volumio volumio-remote-updater[628]: [2026-01-28 14:17:03] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Jan 28 14:17:03 volumio volumio-remote-updater[628]: [2026-01-28 14:17:03] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Jan 28 14:17:03 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+07:00" level=debug msg="app state loaded" Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:03 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 28 14:17:03 volumio systemd[1]: volumio.service: Consumed 59.017s CPU time. Jan 28 14:17:03 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 14:17:03 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 14:17:03 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10239. Jan 28 14:17:03 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 14:17:03 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 28 14:17:03 volumio systemd[1]: volumio.service: Consumed 59.017s CPU time. Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17: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-gew4.spotify.com:80]" Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+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 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+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 28 14:17:03 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 28 14:17:03 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 14:17:03 volumio go-librespot[26739]: time="2026-01-28T14:17:03+07:00" level=info msg="zeroconf server listening on port 39419" Jan 28 14:17:04 volumio go-librespot[26739]: time="2026-01-28T14:17:04+07:00" level=debug msg="obtained new client token: AAC3XrtjyUZKyxjfJjV0CO5zfUWR9Y4XE1UGZUokqMu/vOybweqbnEv7vSvqcf1hMbbQcWzGz1Vw33pMWAV+uGIYPN3ee04UzQ3LO/rPmrWaKNHcD9CuSJxlmt9zp/PSytxHrxynM980UUsZzG4uQXGGB+eLKpdJnYQUnebTziIvyi/E60CDZ5S9AnrFbtRA3C4+3QuuF0JDIzpCR7m+QFJc3+nTjXa9UqdoVde+Oo/7+4tAUxjg3x9w" Jan 28 14:17:04 volumio go-librespot[26739]: time="2026-01-28T14:17:04+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:04 volumio go-librespot[26739]: time="2026-01-28T14:17:04+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:04 volumio go-librespot[26739]: time="2026-01-28T14:17:04+07:00" level=debug msg="completed challenge" Jan 28 14:17:04 volumio go-librespot[26739]: time="2026-01-28T14:17:04+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 28 14:17:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:07 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:07 volumio volumio[26758]: info: ----- Volumio3 ---- Jan 28 14:17:07 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:07 volumio volumio[26758]: info: ----- System startup ---- Jan 28 14:17:07 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 28 14:17:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:07 volumio go-librespot[26782]: go-librespot daemon starting... Jan 28 14:17:07 volumio go-librespot[26783]: time="2026-01-28T14:17:07+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:07 volumio go-librespot[26783]: time="2026-01-28T14:17:07+07:00" level=debug msg="app state loaded" Jan 28 14:17:07 volumio go-librespot[26783]: time="2026-01-28T14:17:07+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+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 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+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 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+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 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+07:00" level=info msg="zeroconf server listening on port 37779" Jan 28 14:17:08 volumio volumio-remote-updater[628]: [2026-01-28 14:17:08] [connect] Successful connection Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+07:00" level=debug msg="obtained new client token: AAC7tFr39k2jA7wZHNAah/le2z/KSa7Ut3bndPxs5O91qA0w6uWXtHt5kXxKBDVvtlqZUih7tGLCzaJgXwG/Wd/AvHdJ5uAPgvfnxoPvrUL5T9Ld7bmEZuLBGM9wRtufq6rp+5q5QQ/nhcNraNUMjJQRxBdwXs6fjaiX/sMP+JeBrOks7H4mrYVdiD7l8O5ZgSVz/fLg9I0r9LaqAufSR0pDS3wXIOVdAKOOaTwjuOlBm5rFMzzvWLH5HE0=" Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+07:00" level=debug msg="completed challenge" Jan 28 14:17:08 volumio go-librespot[26783]: time="2026-01-28T14:17:08+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 28 14:17:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:08 volumio volumio[26758]: info: MYVOLUMIO Environment detected Jan 28 14:17:09 volumio volumio[26758]: info: Plugin folders cleanup Jan 28 14:17:09 volumio volumio[26758]: info: Scanning into folder /volumio/app/plugins/ Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category audio_interface Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category miscellanea Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category music_service Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category plugins.json Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category system_controller Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category user_interface Jan 28 14:17:09 volumio volumio[26758]: info: Scanning into folder /data/plugins/ Jan 28 14:17:09 volumio volumio[26758]: info: Scanning category music_service Jan 28 14:17:09 volumio volumio[26758]: info: Plugin folders cleanup completed Jan 28 14:17:09 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:09 volumio volumio[26758]: info: ----- Core plugins startup ---- Jan 28 14:17:09 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:09 volumio volumio[26758]: info: Loading plugins from folder /volumio/app/plugins/ Jan 28 14:17:09 volumio volumio[26758]: info: Adding plugin upnp to MyMusic Plugins Jan 28 14:17:09 volumio volumio[26758]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 28 14:17:09 volumio volumio[26758]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 28 14:17:09 volumio volumio[26758]: info: Loading plugins from folder /data/plugins/ Jan 28 14:17:09 volumio volumio[26758]: info: Loading plugin "system"... Jan 28 14:17:09 volumio volumio[26758]: info: Loading plugin "appearance"... Jan 28 14:17:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "network"... Jan 28 14:17:11 volumio volumio[26758]: info: Refreshing Cached IP Addresses Jan 28 14:17:11 volumio sudo[26797]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 14:17:11 volumio sudo[26797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:11 volumio sudo[26797]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:11 volumio sudo[26799]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 14:17:11 volumio sudo[26799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "services"... Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "alsa_controller"... Jan 28 14:17:11 volumio sudo[26799]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:11 volumio sudo[26807]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 28 14:17:11 volumio sudo[26807]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:11 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "wizard"... Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "networkfs"... Jan 28 14:17:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:11 volumio volumio[26758]: info: Starting Udev Watcher for removable devices Jan 28 14:17:11 volumio volumio[26758]: info: Ignoring mount for partition: boot Jan 28 14:17:11 volumio volumio[26758]: info: Ignoring mount for partition: volumio Jan 28 14:17:11 volumio volumio[26758]: info: Ignoring mount for partition: volumio_data Jan 28 14:17:11 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "volumio_command_line_client"... Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "upnp"... Jan 28 14:17:11 volumio volumio[26758]: info: [1769584631415] Starting Upmpd Daemon Jan 28 14:17:11 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "my_music"... Jan 28 14:17:11 volumio volumio[26758]: info: Loading plugin "mpd"... Jan 28 14:17:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 28 14:17:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:11 volumio go-librespot[26830]: go-librespot daemon starting... Jan 28 14:17:11 volumio go-librespot[26831]: time="2026-01-28T14:17:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:11 volumio go-librespot[26831]: time="2026-01-28T14:17:11+07:00" level=debug msg="app state loaded" Jan 28 14:17:11 volumio go-librespot[26831]: time="2026-01-28T14:17:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:12 volumio volumio[26758]: info: Loading plugin "upnp_browser"... Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+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 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+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 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+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 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+07:00" level=info msg="zeroconf server listening on port 40901" Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+07:00" level=debug msg="obtained new client token: AAAfyRTHMu7/EmnQiefktIn4vitm6Owk8Vjnuh1bbfS9NVDpaD2f/CQbxBP2qnJzfnNPYxKEo0KWYf5CAiXndn5Da0YP2hMpsaKHzbOb+uZI2vEwR/pVcsepW+1fXWG9rV0Stbh4R0/yD6E+IKpgsEXWHpW1ZYtxakhOiY01+FobN5n6NDFKTp+DnR06E/0EWog756WfCVk06aceod0sp2fZwF5y3ak2/1kcd5D3NcMe7eTOBQjA0dzvSjo=" Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17:12+07:00" level=debug msg="completed challenge" Jan 28 14:17:12 volumio go-librespot[26831]: time="2026-01-28T14:17: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 28 14:17:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:13 volumio sudo[26807]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:15 volumio volumio[26758]: info: Starting UPNP Browser Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "alarm-clock"... Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "airplay_emulation"... Jan 28 14:17:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:15 volumio volumio[26758]: info: Starting Shairport Sync Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "last_100"... Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "webradio"... Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "i2s_dacs"... Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "volumiodiscovery"... Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:17:15 volumio node[26758]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** For more information see Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:17:15 volumio volumio[26758]: *** WARNING *** For more information see Jan 28 14:17:15 volumio node[26758]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:17:15 volumio node[26758]: *** WARNING *** For more information see Jan 28 14:17:15 volumio node[26758]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 14:17:15 volumio node[26758]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 14:17:15 volumio node[26758]: *** WARNING *** For more information see Jan 28 14:17:15 volumio volumio[26758]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 28 14:17:15 volumio volumio[26758]: info: Discovery: Started advertising with name: Volumio Jan 28 14:17:15 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 14:17:15 volumio volumio[26758]: info: Loading plugin "spop"... Jan 28 14:17:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 28 14:17:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:16 volumio go-librespot[26840]: go-librespot daemon starting... Jan 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17:16+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17:16+07:00" level=debug msg="app state loaded" Jan 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17:16+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17: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 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17: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 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17: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 28 14:17:16 volumio go-librespot[26841]: time="2026-01-28T14:17:16+07:00" level=info msg="zeroconf server listening on port 42427" Jan 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+07:00" level=debug msg="obtained new client token: AACWDxCgoNPcCjaDEG73LxfexIBUdnVeEZynRzjRPSztqbjZ6LYXO8nObVGeeq2VcQbCejmJ7KlskOhFpU/LAgQGduOxG3pvNMSENOyqRVny9Tl3cWKKR6z6i7COz5opMLGGbenWaF5Q2lyIr1AuZzvdyDCkoNmG5eIQtgJOfnuGcQSUFih8iX+TB0p/z7Ki97+Dp1QmWTcXT0xW4W8QUuUpS+89TbEdOLB0itAiG7aLie+ajvfzM0Sd" Jan 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+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 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 28 14:17:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+07:00" level=debug msg="completed challenge" Jan 28 14:17:17 volumio go-librespot[26841]: time="2026-01-28T14:17:17+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 28 14:17:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:17 volumio volumio[26758]: info: Loading plugin "ytcr"... Jan 28 14:17:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:20 volumio volumio[26758]: info: Loading plugin "ytmusic"... Jan 28 14:17:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 28 14:17:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:20 volumio go-librespot[26849]: go-librespot daemon starting... Jan 28 14:17:20 volumio volumio-remote-updater[628]: [2026-01-28 14:17:20] [connect] Successful connection Jan 28 14:17:20 volumio go-librespot[26850]: time="2026-01-28T14:17:20+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:20 volumio go-librespot[26850]: time="2026-01-28T14:17:20+07:00" level=debug msg="app state loaded" Jan 28 14:17:20 volumio go-librespot[26850]: time="2026-01-28T14:17:20+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "outputs"... Jan 28 14:17:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+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 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+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 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+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 28 14:17:21 volumio volumio[26758]: info: Loading plugin "albumart"... Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+07:00" level=info msg="zeroconf server listening on port 46717" Jan 28 14:17:21 volumio volumio[26758]: info: Plugin example_plugin is not enabled Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "inputs"... Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "updater_comm"... Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+07:00" level=debug msg="obtained new client token: AADhA0LZUsBbczLUHRiEn/0fxtauDip7DtJ9dZPXoA+sjDo4QbXGeHaX7d/NETd2CJu8bNICpgPavh68rt7f3+/H1dINM2WvMUno4ERmw3belpVT1DpbEcH4P4c1E4zxQA6dbTId4oyPUV/Eqv/Q8xrCxYx11SfIlytpL5aMBcpiKC1NMRAkGJDtPzSMCdehr3NP6T8/pAJnSydEPtabTCN5RebGhyFaQc7QwfYGyN7ZDFEahrynauOmDDQ=" Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:21 volumio volumio[26758]: info: Plugin mpdemulation is not enabled Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "rest_api"... Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+07:00" level=debug msg="completed challenge" Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "websocket"... Jan 28 14:17:21 volumio go-librespot[26850]: time="2026-01-28T14:17:21+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 28 14:17:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:21 volumio volumio[26758]: info: Starting Socket.io Server version 1.7.4 Jan 28 14:17:21 volumio volumio[26758]: info: Loading plugin "RoonBridge"... Jan 28 14:17:22 volumio volumio[26758]: info: Applying required configuration parameters for plugin RoonBridge Jan 28 14:17:22 volumio volumio[26758]: info: Loading i18n strings for locale en Jan 28 14:17:22 volumio volumio[26758]: Updating browse sources language Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:22 volumio volumio[26871]: Forking 3 albumart workers Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::initPlayerControls Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:17:22 volumio volumio[26758]: Express server listening on port 3000 Jan 28 14:17:22 volumio volumio[26758]: [Metrics] WebUI: 16s 170.29ms Jan 28 14:17:22 volumio volumio[26758]: info: CoreStateMachine::resetVolumioState Jan 28 14:17:22 volumio volumio[26758]: info: CoreStateMachine::getcurrentVolume Jan 28 14:17:22 volumio volumio[26758]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:17:22 volumio sudo[26916]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 14:17:22 volumio sudo[26916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:22 volumio sudo[26918]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 14:17:22 volumio sudo[26916]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:22 volumio sudo[26918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:22 volumio sudo[26918]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:23 volumio volumio[26758]: info: Volumio Network Manager: Network status updated: 1 Jan 28 14:17:23 volumio volumio[26758]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::pushState Jan 28 14:17:23 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::volumioPushState Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::updateTrackBlock Jan 28 14:17:23 volumio volumio[26758]: info: CorePlayQueue::getTrackBlock Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:17:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:23 volumio volumio-remote-updater[628]: [2026-01-28 14:17:23] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769584640 101 Jan 28 14:17:23 volumio volumio[26758]: 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 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:23 volumio volumio[26758]: info: Reloading queue from file Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::setRepeat null single undefined Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::pushState Jan 28 14:17:23 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::volumioPushState Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::setRandom null Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::pushState Jan 28 14:17:23 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::volumioPushState Jan 28 14:17:23 volumio volumio[26758]: info: Setting Device type: Raspberry PI Jan 28 14:17:23 volumio volumio[26758]: info: Completed loading Core Plugins Jan 28 14:17:23 volumio volumio[26758]: info: Preparing to generate the ALSA configuration file Jan 28 14:17:23 volumio volumio[26758]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:17:23 volumio volumio[26758]: info: CoreStateMachine::pushState Jan 28 14:17:23 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::volumioPushState Jan 28 14:17:23 volumio volumio[26758]: info: Asound.conf file unchanged, so no further update is needed Jan 28 14:17:23 volumio volumio[26758]: info: Output device has changed, restarting MPD Jan 28 14:17:23 volumio sudo[26931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 28 14:17:23 volumio sudo[26931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:23 volumio volumio[26758]: info: Output device has changed, restarting Shairport Sync Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:23 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:23 volumio sudo[26933]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 14:17:23 volumio sudo[26933]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:23 volumio sudo[26933]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:24 volumio volumio[26758]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:17:24 volumio sudo[26936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 14:17:24 volumio sudo[26936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:24 volumio volumio[26758]: info: ___________ START PLUGINS ___________ Jan 28 14:17:24 volumio sudo[26931]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:24 volumio volumio[26758]: info: ControllerMpd::onStart: Initializing MPD Jan 28 14:17:24 volumio volumio[26758]: info: Creating MPD Configuration file Jan 28 14:17:24 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:17:24 volumio volumio[26758]: info: [1769584644140] CoreMusicLibrary::Adding element Media Servers Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:24 volumio volumio[26758]: info: UPNP Browser: Client initialized successfully Jan 28 14:17:24 volumio sudo[26946]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 14:17:24 volumio sudo[26946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:24 volumio sudo[26945]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 14:17:24 volumio sudo[26945]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:24 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 14:17:24 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 14:17:24 volumio systemd[1]: mpd.service: Consumed 7.511s CPU time. Jan 28 14:17:24 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 14:17:24 volumio sudo[26945]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:24 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 14:17:24 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 14:17:24 volumio volumio[26758]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:24 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 14:17:24 volumio volumio[26758]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:17:24 volumio volumio[26758]: info: [1769584644400] CoreMusicLibrary::Adding element Last_100 Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:24 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:17:24 volumio volumio[26758]: info: [1769584644437] CoreMusicLibrary::Adding element Webradio Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:17:24 volumio volumio[26758]: info: Initializing BBC Radios Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:24 volumio volumio[26758]: info: Creating Spotify config file Jan 28 14:17:24 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:24 volumio sudo[26958]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 28 14:17:24 volumio sudo[26958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 28 14:17:24 volumio sudo[26958]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 28 14:17:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:25 volumio go-librespot[26974]: go-librespot daemon starting... Jan 28 14:17:25 volumio go-librespot[26975]: time="2026-01-28T14:17:25+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:25 volumio volumio[26883]: Starting albumart workers Jan 28 14:17:25 volumio go-librespot[26975]: time="2026-01-28T14:17:25+07:00" level=info msg="zeroconf server listening on port 46503" Jan 28 14:17:25 volumio volumio[26882]: Starting albumart workers Jan 28 14:17:26 volumio volumio[26881]: Starting albumart workers Jan 28 14:17:26 volumio volumio[26758]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:17:26 volumio volumio[26758]: info: [1769584646137] CoreMusicLibrary::Adding element YouTube Music Jan 28 14:17:26 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:26 volumio volumio[26758]: Cannot find translation for source YouTube Music Jan 28 14:17:26 volumio volumio[26758]: info: Volumio Calling Home Jan 28 14:17:26 volumio sudo[26984]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 28 14:17:26 volumio sudo[26984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:26 volumio sudo[26984]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:27 volumio volumio[26758]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:17:27 volumio volumio[26758]: info: Discovery: Found device Volumio Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:27 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:27 volumio volumio[26758]: info: MPD Permissions set Jan 28 14:17:27 volumio volumio[26758]: info: MPD Permissions set Jan 28 14:17:27 volumio volumio[26758]: info: Upmpdcli Daemon Started Jan 28 14:17:27 volumio volumio[26758]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 14:17:27 volumio volumio[26758]: info: Discovery: Found device Volumio Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:27 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:27 volumio volumio[26758]: info: Spotify config file written Jan 28 14:17:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:27 volumio sudo[26990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 14:17:27 volumio sudo[26990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:27 volumio volumio[26758]: 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 28 14:17:27 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 14:17:27 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 14:17:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:27 volumio go-librespot[26998]: go-librespot daemon starting... Jan 28 14:17:27 volumio sudo[26990]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 14:17:27 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 14:17:27 volumio go-librespot[27004]: time="2026-01-28T14:17:27+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:27 volumio go-librespot[27004]: time="2026-01-28T14:17:27+07:00" level=debug msg="app state loaded" Jan 28 14:17:27 volumio go-librespot[27004]: time="2026-01-28T14:17:27+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:27 volumio volumio[26758]: info: No need to fix Spotify hosts Jan 28 14:17:28 volumio volumio[26758]: info: Volumio called home Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+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 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+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 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=info msg="zeroconf server listening on port 38525" Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=debug msg="obtained new client token: AADdRiWdJTTfbppkf194VkEf5aW9HMst+ghj9oZy4lLfSFc1plkk3T4+EJZh4hQsXkivtJlWDxurJdm2msM/wy6qkiU3y6o0hzbekc8nKXAOCKzxG8QEHOeRHpAaDYZP3C154DnAQHktwlbW3ggs+UBdTou4kKFUn+9RYHQwrhMAX8fHGbDBG7XG8SHTowdjZ1VxMlVAPdX4HqKVbyNfDAsr5li3B6j3YoP6ckSuUWlr7DahoylEKrzO1b8=" Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:28 volumio volumio[26758]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:17:28 volumio volumio[26758]: SPOTIFY: BQANYKrvT6srGj-Dkze9K7BTTXC58-Bs9SGwu5pDou-pIR9vg7_TFLCN-gCfdlXhuSGRuLCwPnlGXBXJTZpiGbvSOFI05aOejX4AW8QsiSXsSEsi2xHom_cqgkQ1Xu_4zkmgijOTRMs6Q-BHWqoU52xhGQLec7iSVdFTXOIHSEXiMndGyX-_05axF2JxtYiti5GAO5F_wpFi_n9USpBXlr7jAdBhuO6QdVM1cStj99cR5VOperyXSZNRM8NiZPDXChBZQC1oUakOOBvP6h0Nq9JW2mFdx1ClPtKomYr4A7xGxFdlE0yPKRzt Jan 28 14:17:28 volumio volumio[26758]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 14:17:28 volumio volumio[26758]: info: New Spotify access token = BQANYKrvT6srGj-Dkze9K7BTTXC58-Bs9SGwu5pDou-pIR9vg7_TFLCN-gCfdlXhuSGRuLCwPnlGXBXJTZpiGbvSOFI05aOejX4AW8QsiSXsSEsi2xHom_cqgkQ1Xu_4zkmgijOTRMs6Q-BHWqoU52xhGQLec7iSVdFTXOIHSEXiMndGyX-_05axF2JxtYiti5GAO5F_wpFi_n9USpBXlr7jAdBhuO6QdVM1cStj99cR5VOperyXSZNRM8NiZPDXChBZQC1oUakOOBvP6h0Nq9JW2mFdx1ClPtKomYr4A7xGxFdlE0yPKRzt Jan 28 14:17:28 volumio volumio[26758]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 14:17:28 volumio volumio[26758]: info: Starting Shairport Sync Jan 28 14:17:28 volumio volumio[26758]: info: Starting Shairport Sync Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17:28+07:00" level=debug msg="completed challenge" Jan 28 14:17:28 volumio volumio[26758]: info: Starting Shairport Sync Jan 28 14:17:28 volumio sudo[27031]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:17:28 volumio sudo[27031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:28 volumio go-librespot[27004]: time="2026-01-28T14:17: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 28 14:17:28 volumio sudo[27033]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:17:28 volumio sudo[27033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:29 volumio sudo[27035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 14:17:29 volumio sudo[27035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 14:17:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 14:17:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 14:17:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:17:29 volumio systemd[1]: shairport-sync.service: Consumed 2.373s CPU time. Jan 28 14:17:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 14:17:29 volumio sudo[27033]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:29 volumio sudo[27031]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:29 volumio sudo[27035]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:29 volumio volumio[26758]: info: Shairport-Sync Started Jan 28 14:17:29 volumio volumio[26758]: Error adding Membership: Error: addMembership EINVAL Jan 28 14:17:29 volumio volumio[26758]: info: Shairport-Sync Started Jan 28 14:17:29 volumio volumio[26758]: info: Shairport-Sync Started Jan 28 14:17:29 volumio volumio[26758]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:29 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:29 volumio volumio[26758]: 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 28 14:17:29 volumio volumio[26758]: info: Spotify Successfully logged in Jan 28 14:17:29 volumio volumio[26758]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 14:17:29 volumio volumio[26758]: info: [1769584649763] CoreMusicLibrary::Adding element Spotify Jan 28 14:17:29 volumio volumio[26758]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 14:17:29 volumio volumio[26758]: Cannot find translation for source YouTube Music Jan 28 14:17:29 volumio volumio[26758]: Cannot find translation for source Spotify Jan 28 14:17:30 volumio volumio[26758]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 28 14:17:30 volumio volumio[26758]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 14:17:30 volumio volumio[26758]: info: VolumeController:: Volume=100 Mute =false Jan 28 14:17:30 volumio volumio[26758]: info: CoreCommandRouter::volumioGetState Jan 28 14:17:30 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:30 volumio volumio[26758]: info: CoreStateMachine::pushState Jan 28 14:17:30 volumio volumio[26758]: info: CorePlayQueue::getTrack 0 Jan 28 14:17:30 volumio volumio[26758]: info: CoreCommandRouter::volumioPushState Jan 28 14:17:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:31 volumio volumio[26758]: info: go-librespot daemon successfully initialized Jan 28 14:17:31 volumio mpd[26973]: 2026-01-28T14:17:31 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 28 14:17:31 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 28 14:17:31 volumio sudo[26946]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:31 volumio sudo[26936]: pam_unix(sudo:session): session closed for user root Jan 28 14:17:32 volumio volumio[26758]: error: MPD error: The expression evaluated to a falsy value: Jan 28 14:17:32 volumio volumio[26758]: assert.ok(self.idling) Jan 28 14:17:32 volumio volumio[26758]: error: The expression evaluated to a falsy value: Jan 28 14:17:32 volumio volumio[26758]: assert.ok(self.idling) Jan 28 14:17:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 14:17:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:32 volumio volumio[26758]: info: MPD running with PID26973 Jan 28 14:17:32 volumio volumio[26758]: ,establishing connection Jan 28 14:17:32 volumio volumio[26758]: error: updateQueue error: null Jan 28 14:17:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:32 volumio go-librespot[27074]: go-librespot daemon starting... Jan 28 14:17:32 volumio volumio[26758]: info: Completed starting Core Plugins Jan 28 14:17:32 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:32 volumio volumio[26758]: info: ----- MyVolumio plugins startup ---- Jan 28 14:17:32 volumio volumio[26758]: info: ------------------------------------------- Jan 28 14:17:32 volumio volumio[26758]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 28 14:17:32 volumio volumio[26758]: error: updateQueue error: null Jan 28 14:17:32 volumio go-librespot[27075]: time="2026-01-28T14:17:32+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:32 volumio go-librespot[27075]: time="2026-01-28T14:17:32+07:00" level=debug msg="app state loaded" Jan 28 14:17:32 volumio go-librespot[27075]: time="2026-01-28T14:17:32+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+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 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+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 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+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 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+07:00" level=info msg="zeroconf server listening on port 38299" Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+07:00" level=debug msg="obtained new client token: AAA96KNLLkRysZrmLNQO8NS2lNF8MuidIOePQAGqxlcht2cf6+cPeWii4FfQ8hiWwywdoR7yNymjAWHxoEwDyqlqT4Ij+ZF1F/RjQEu1EwBFw6xVhFCxoobcqeC/L/+mHj03eHUXmkbTsc/qizMx+cSWaSs7A2iV6PT8ttbJ8YtWWl7VGx8R3wbCQSC75wTHMTqPznt3w+i98lJbiJNIqnjPiQSrcr4CrWJZwPDwrsw0w6VN1XjCYIEZ" Jan 28 14:17:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+07:00" level=debug msg="completed challenge" Jan 28 14:17:33 volumio go-librespot[27075]: time="2026-01-28T14:17:33+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 28 14:17:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:34 volumio volumio[26758]: info: Initializing connection to go-librespot Websocket Jan 28 14:17:34 volumio volumio[26758]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:17:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 28 14:17:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:36 volumio go-librespot[27084]: go-librespot daemon starting... Jan 28 14:17:36 volumio go-librespot[27085]: time="2026-01-28T14:17:36+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:36 volumio go-librespot[27085]: time="2026-01-28T14:17:36+07:00" level=debug msg="app state loaded" Jan 28 14:17:36 volumio go-librespot[27085]: time="2026-01-28T14:17:36+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:37 volumio volumio[26758]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+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 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+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 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+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 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=info msg="zeroconf server listening on port 39239" Jan 28 14:17:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=debug msg="obtained new client token: AABF2+1ZFQcRQYHzGu0I4qifVT/jOK94L0ISX9LXYVGT0HjHDl91tW8pSYwy9IVIhSaoy2xpxBPM8yLJBsKGrHFXR012Jt8TU5kle8RErtMNIFrXrbi7JKdKXGQiauShAaSeG6fo39dvOuKPUSqeneypyxS7ceSry16kCbf8WAGrsG8MiC83jnaO7i8vKPVzTgmWSTd51LVw0chfynBi2TLfZif9/ldHjSPJIV/z6mu86HDVLTAN0hOh7ow=" Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:37 volumio volumio[26758]: info: Initializing connection to go-librespot Websocket Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=debug msg="completed challenge" Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+07:00" level=debug msg="new websocket client" Jan 28 14:17:37 volumio volumio[26758]: info: Connection to go-librespot Websocket established Jan 28 14:17:37 volumio go-librespot[27085]: time="2026-01-28T14:17:37+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 28 14:17:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:37 volumio volumio[26758]: info: Connection to go-librespot Websocket closed Jan 28 14:17:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:40 volumio volumio[26758]: info: Getting Spotify volume Jan 28 14:17:40 volumio volumio[26758]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:17:40 volumio volumio[26758]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 14:17:40 volumio volumio[26758]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 28 14:17:40 volumio volumio[26758]: errno: -111, Jan 28 14:17:40 volumio volumio[26758]: code: 'ECONNREFUSED', Jan 28 14:17:40 volumio volumio[26758]: syscall: 'connect', Jan 28 14:17:40 volumio volumio[26758]: address: '127.0.0.1', Jan 28 14:17:40 volumio volumio[26758]: port: 9879, Jan 28 14:17:40 volumio volumio[26758]: response: undefined Jan 28 14:17:40 volumio volumio[26758]: } Jan 28 14:17:40 volumio volumio[26758]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 14:17:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 28 14:17:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 14:17:41 volumio go-librespot[27104]: go-librespot daemon starting... Jan 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17:41+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17:41+07:00" level=debug msg="app state loaded" Jan 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17:41+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 14:17:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 14:17:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 14:17:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17: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 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17: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 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17: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 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17:41+07:00" level=info msg="zeroconf server listening on port 46341" Jan 28 14:17:41 volumio go-librespot[27106]: time="2026-01-28T14:17:41+07:00" level=debug msg="obtained new client token: AABWXbNjTVMERZX/szXs2R4XU9LREHN9uB9aPFcrHO5zRQe15UL0ZcMF8OZyvKWqOuAPt6sUkDFZuNwh2wLKmlutrgfFRzaKusdGK9YsvDnyV1Q3n/x+Z1LgNfbcmcdpoiu1sSspHAFYiiMAMcVsBb82E8UTe9HooX0lZWoSG16Auq2p23/yN0W2tck5SzY+cN7RFUJrHb/sdbG2tdlI0kssv+v8mURJvOByvBbuyE5VduKRIEoGOWnS+qM=" Jan 28 14:17:42 volumio go-librespot[27106]: time="2026-01-28T14:17:42+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 28 14:17:42 volumio go-librespot[27106]: time="2026-01-28T14:17:42+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 28 14:17:42 volumio go-librespot[27106]: time="2026-01-28T14:17:42+07:00" level=debug msg="completed keyexchange" Jan 28 14:17:42 volumio go-librespot[27106]: time="2026-01-28T14:17:42+07:00" level=debug msg="completed challenge" Jan 28 14:17:42 volumio go-librespot[27106]: time="2026-01-28T14:17:42+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 28 14:17:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 14:17:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 14:17:42 volumio sudo[27129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 14:16' Jan 28 14:17:42 volumio sudo[27129]: 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"