Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:01 volumio sudo[27917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:21' Jan 27 22:22:01 volumio sudo[27917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:01 volumio sudo[27917]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:01 volumio volumio-remote-updater[628]: [2026-01-27 22:22:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 27 22:22:01 volumio volumio-remote-updater[628]: [2026-01-27 22:22:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 27 22:22:01 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:01 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Consumed 58.982s CPU time. Jan 27 22:22:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 9233. Jan 27 22:22:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:01 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 22:22:01 volumio systemd[1]: volumio.service: Consumed 58.982s CPU time. Jan 27 22:22:01 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 22:22:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 27 22:22:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:02 volumio go-librespot[27947]: go-librespot daemon starting... Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=debug msg="app state loaded" Jan 27 22:22:02 volumio go-librespot[27948]: time="2026-01-27T22:22:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=info msg="zeroconf server listening on port 37437" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="obtained new client token: AABOC+J4SJdHXFS7e13tgW9n8WTTxPfF8D+J8v5hyI6CTYwcClvGAeAqkkQZTeC4hCD/hRJ3h7h5Ca5UVEkEArUHCavO3SnytmAAQCl1cjCz54+vwen8c7ylZGAIJXoleqzQEh+39OBO9S0BqX/pEabQRWkUZz+TH9TAfrWQXvRb/KAJMYcqrgvV8zN2ARdiU3sXiR0ovZlXU4Bwo7dUm5wLHouAEzOTZYbkB1dSBdtY7l3rxb2ZcNUVZ84=" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=debug msg="completed challenge" Jan 27 22:22:03 volumio go-librespot[27948]: time="2026-01-27T22:22:03+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:05 volumio volumio[27932]: info: ----- Volumio3 ---- Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:05 volumio volumio[27932]: info: ----- System startup ---- Jan 27 22:22:05 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:06 volumio volumio-remote-updater[628]: [2026-01-27 22:22:06] [connect] Successful connection Jan 27 22:22:06 volumio volumio[27932]: info: MYVOLUMIO Environment detected Jan 27 22:22:06 volumio volumio[27932]: info: Plugin folders cleanup Jan 27 22:22:06 volumio volumio[27932]: info: Scanning into folder /volumio/app/plugins/ Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category audio_interface Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category miscellanea Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category music_service Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category plugins.json Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category system_controller Jan 27 22:22:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 27 22:22:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:06 volumio volumio[27932]: info: Scanning category user_interface Jan 27 22:22:06 volumio volumio[27932]: info: Scanning into folder /data/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Scanning category music_service Jan 27 22:22:07 volumio volumio[27932]: info: Plugin folders cleanup completed Jan 27 22:22:07 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:07 volumio volumio[27932]: info: ----- Core plugins startup ---- Jan 27 22:22:07 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin upnp to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugins from folder /data/plugins/ Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugin "system"... Jan 27 22:22:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:07 volumio go-librespot[27965]: go-librespot daemon starting... Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:07 volumio volumio[27932]: info: Loading plugin "appearance"... Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="app state loaded" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=info msg="zeroconf server listening on port 36065" Jan 27 22:22:07 volumio go-librespot[27966]: time="2026-01-27T22:22:07+07:00" level=debug msg="obtained new client token: AADGWRvvjWdyIRY0TFTsYW7GZK3aH8gT0Zn6iioO+fIojJ9lXwrx507B6n6MK9dfxiKZ6RCx2NP28s02gcQvhzOJiCeGsi1wTEVygADxUjmo5AscCu9PLWVyiRAQwdEF/++QPxDELKSCEIqQNPim8w4N0s1qftWvUInTEth62xN4BWJ8ljIYc+wtT9G126TF/701aH05QUCItzq22bssAlCR+9MjrgMvKL6Hf27SBPtMhOZBPpA8NR7vZsc=" Jan 27 22:22:08 volumio go-librespot[27966]: time="2026-01-27T22:22:08+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:08 volumio go-librespot[27966]: time="2026-01-27T22:22:08+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "network"... Jan 27 22:22:09 volumio volumio[27932]: info: Refreshing Cached IP Addresses Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:09 volumio sudo[27977]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:22:09 volumio sudo[27977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio sudo[27977]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "services"... Jan 27 22:22:09 volumio sudo[27979]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:22:09 volumio sudo[27979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "alsa_controller"... Jan 27 22:22:09 volumio sudo[27987]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 22:22:09 volumio sudo[27987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:09 volumio sudo[27979]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "wizard"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "networkfs"... Jan 27 22:22:09 volumio volumio[27932]: info: Starting Udev Watcher for removable devices Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: boot Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: volumio Jan 27 22:22:09 volumio volumio[27932]: info: Ignoring mount for partition: volumio_data Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "volumio_command_line_client"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "upnp"... Jan 27 22:22:09 volumio volumio[27932]: info: [1769527329477] Starting Upmpd Daemon Jan 27 22:22:09 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "my_music"... Jan 27 22:22:09 volumio volumio[27932]: info: Loading plugin "mpd"... Jan 27 22:22:10 volumio volumio[27932]: info: Loading plugin "upnp_browser"... Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 27 22:22:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:11 volumio go-librespot[28011]: go-librespot daemon starting... Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=debug msg="app state loaded" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:22:11 volumio go-librespot[28012]: time="2026-01-27T22:22:11+07:00" level=info msg="zeroconf server listening on port 33153" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="obtained new client token: AACbdi5NUQ++y4FPJMShmDLsx20ZoOq3BKRZDtKmpYVHO8jqzHhbisq5Y7H/h5lOYFK1+cupwpUcgzZdFUFlWKTkP8urwU74ULzUWexvjbZWZYSiGsH/66egdz1hlhGd+21+kqAc7qPAZ529JnzpilFqSgskcDzozDt+mNK/SYZT5JXX9rMojTBqyLazndHox8vCDz5XnuSjiSdM6Q5dCU//kQf06iVyWnU8JCKMapjUoBueajWUyjTq" Jan 27 22:22:12 volumio sudo[27987]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=debug msg="completed challenge" Jan 27 22:22:12 volumio go-librespot[28012]: time="2026-01-27T22:22:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:13 volumio volumio[27932]: info: Starting UPNP Browser Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "alarm-clock"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "airplay_emulation"... Jan 27 22:22:13 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "last_100"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "webradio"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "i2s_dacs"... Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "volumiodiscovery"... Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio volumio[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio node[27932]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio node[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio node[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio node[27932]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:13 volumio node[27932]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:13 volumio node[27932]: *** WARNING *** For more information see Jan 27 22:22:13 volumio volumio[27932]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 22:22:13 volumio volumio[27932]: info: Discovery: Started advertising with name: Volumio Jan 27 22:22:13 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:13 volumio volumio[27932]: info: Loading plugin "spop"... Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 27 22:22:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:15 volumio go-librespot[28021]: go-librespot daemon starting... Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=debug msg="app state loaded" Jan 27 22:22:15 volumio go-librespot[28022]: time="2026-01-27T22:22:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:15 volumio volumio[27932]: info: Loading plugin "ytcr"... Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=info msg="zeroconf server listening on port 39963" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="obtained new client token: AAABtY/g2ywzHIT8Pocmqh2Qs2lCOT3lKJNP1xoRpZuazrYQvAhWJNT4Y2Cz6fzgpKuz0B+3P3FX5rhwReD1aEmLQHdfQk76nHBxiuVMwu4Gzxfc9ATB5KJwcGNCC3zbGX8IUGDFY6FQkUCUrvT/mYN4+3v2AVwlqfGtiEq4qdx/96/OZTBFjaXYjZZkp6EECBjdjHwatIbUfcfRvDcMoZOxhP9IQYrW8oSOV+iuVct41ssRRJhtWgZTt4g=" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=debug msg="completed challenge" Jan 27 22:22:16 volumio go-librespot[28022]: time="2026-01-27T22:22:16+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:18 volumio volumio[27932]: info: Loading plugin "ytmusic"... Jan 27 22:22:19 volumio volumio-remote-updater[628]: [2026-01-27 22:22:19] [connect] Successful connection Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "outputs"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "albumart"... Jan 27 22:22:19 volumio volumio[27932]: info: Plugin example_plugin is not enabled Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "inputs"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "updater_comm"... Jan 27 22:22:19 volumio volumio[27932]: info: Plugin mpdemulation is not enabled Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "rest_api"... Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "websocket"... Jan 27 22:22:19 volumio volumio[27932]: info: Starting Socket.io Server version 1.7.4 Jan 27 22:22:19 volumio volumio[27932]: info: Loading plugin "RoonBridge"... Jan 27 22:22:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 27 22:22:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:20 volumio go-librespot[28055]: go-librespot daemon starting... Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="app state loaded" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:20 volumio volumio[27932]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 22:22:20 volumio volumio[27932]: info: Loading i18n strings for locale en Jan 27 22:22:20 volumio volumio[27932]: Updating browse sources language Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:20 volumio volumio[28045]: Forking 3 albumart workers Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=info msg="zeroconf server listening on port 42473" Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::initPlayerControls Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:20 volumio volumio[27932]: Express server listening on port 3000 Jan 27 22:22:20 volumio volumio[27932]: [Metrics] WebUI: 16s 274.54ms Jan 27 22:22:20 volumio volumio[27932]: info: CoreStateMachine::resetVolumioState Jan 27 22:22:20 volumio volumio[27932]: info: CoreStateMachine::getcurrentVolume Jan 27 22:22:20 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:20 volumio go-librespot[28056]: time="2026-01-27T22:22:20+07:00" level=debug msg="obtained new client token: AAATozMoT6ZFAmkDgZB2oGhpLMyCFm8kaH+BmN7EucNpbB5x6ta0XallcNOO2veZON5HXQpjmONKJ3rthzrRGkM3MStjEj7MMKiax2xJq2thHVeiyfF+jGM0XdnOezGUUG44LSWzLQp39Wf5cwwWrl36B0RAe4Jp0eHwWcJTSJrdvutW+Ij2GlcbpP14APCaCdHzWcrqqEwgM723tyCXx41KbfwH7xpgMeo1SSPCKiyAPdM6DSf+k7BTIcA=" Jan 27 22:22:21 volumio go-librespot[28056]: time="2026-01-27T22:22:21+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:21 volumio sudo[28098]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:22:21 volumio sudo[28098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:21 volumio sudo[28098]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:21 volumio volumio[27932]: info: Volumio Network Manager: Network status updated: 1 Jan 27 22:22:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:21 volumio sudo[28100]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:22:21 volumio go-librespot[28056]: time="2026-01-27T22:22:21+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:21 volumio sudo[28100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:21 volumio sudo[28100]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:21 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::updateTrackBlock Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrackBlock Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:21 volumio volumio-remote-updater[628]: [2026-01-27 22:22:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769527339 101 Jan 27 22:22:21 volumio volumio[27932]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:21 volumio volumio[27932]: info: Reloading queue from file Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::setRepeat null single undefined Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::setRandom null Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: Setting Device type: Raspberry PI Jan 27 22:22:21 volumio volumio[27932]: info: Completed loading Core Plugins Jan 27 22:22:21 volumio volumio[27932]: info: Preparing to generate the ALSA configuration file Jan 27 22:22:21 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:21 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:21 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:21 volumio volumio[27932]: info: Asound.conf file unchanged, so no further update is needed Jan 27 22:22:21 volumio volumio[27932]: info: Output device has changed, restarting MPD Jan 27 22:22:21 volumio volumio[27932]: info: Output device has changed, restarting Shairport Sync Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:21 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:21 volumio sudo[28114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 22:22:21 volumio sudo[28114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio sudo[28116]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:22:22 volumio sudo[28116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio sudo[28116]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio sudo[28118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:22:22 volumio sudo[28118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio volumio[27932]: info: ___________ START PLUGINS ___________ Jan 27 22:22:22 volumio volumio[27932]: info: ControllerMpd::onStart: Initializing MPD Jan 27 22:22:22 volumio volumio[27932]: info: Creating MPD Configuration file Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342176] CoreMusicLibrary::Adding element Media Servers Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 22:22:22 volumio sudo[28129]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:22:22 volumio sudo[28129]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio sudo[28114]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio volumio[27932]: info: UPNP Browser: Client initialized successfully Jan 27 22:22:22 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:22:22 volumio sudo[28127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:22:22 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:22:22 volumio sudo[28127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:22 volumio systemd[1]: mpd.service: Consumed 7.425s CPU time. Jan 27 22:22:22 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:22:22 volumio sudo[28127]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:22:22 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:22:22 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio volumio[27932]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342634] CoreMusicLibrary::Adding element Last_100 Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:22 volumio volumio[27932]: info: [1769527342653] CoreMusicLibrary::Adding element Webradio Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:22 volumio volumio[27932]: info: Initializing BBC Radios Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:22 volumio sudo[28137]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 22:22:22 volumio sudo[28137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 22:22:22 volumio sudo[28137]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:22 volumio volumio[27932]: info: Creating Spotify config file Jan 27 22:22:22 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:23 volumio volumio[28066]: Starting albumart workers Jan 27 22:22:23 volumio volumio[28065]: Starting albumart workers Jan 27 22:22:24 volumio volumio[28064]: Starting albumart workers Jan 27 22:22:24 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:24 volumio volumio[27932]: info: [1769527344228] CoreMusicLibrary::Adding element YouTube Music Jan 27 22:22:24 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:24 volumio volumio[27932]: Cannot find translation for source YouTube Music Jan 27 22:22:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 27 22:22:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:24 volumio volumio[27932]: info: Volumio Calling Home Jan 27 22:22:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:24 volumio go-librespot[28157]: go-librespot daemon starting... Jan 27 22:22:24 volumio go-librespot[28162]: time="2026-01-27T22:22:24+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:24 volumio sudo[28159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 22:22:24 volumio sudo[28159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:24 volumio sudo[28159]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:25 volumio go-librespot[28162]: time="2026-01-27T22:22:25+07:00" level=info msg="zeroconf server listening on port 38529" Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: Found device Volumio Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:25 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:22:25 volumio volumio[27932]: info: Discovery: Found device Volumio Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:25 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:25 volumio volumio[27932]: info: MPD Permissions set Jan 27 22:22:25 volumio volumio[27932]: info: MPD Permissions set Jan 27 22:22:25 volumio volumio[27932]: info: Upmpdcli Daemon Started Jan 27 22:22:25 volumio volumio[27932]: info: Spotify config file written Jan 27 22:22:25 volumio volumio[27932]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 27 22:22:25 volumio volumio[27932]: info: Volumio called home Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio sudo[28172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 22:22:25 volumio sudo[28172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:22:25 volumio volumio[27932]: info: No need to fix Spotify hosts Jan 27 22:22:25 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 22:22:25 volumio systemd[1]: go-librespot-daemon.service: Killing process 28166 (go-librespot) with signal SIGKILL. Jan 27 22:22:25 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 22:22:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:26 volumio go-librespot[28191]: go-librespot daemon starting... Jan 27 22:22:26 volumio sudo[28172]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=debug msg="app state loaded" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:26 volumio go-librespot[28194]: time="2026-01-27T22:22:26+07:00" level=info msg="zeroconf server listening on port 44761" Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: BQCqm4hFtWrs4W0KGpO-E9oh-1smLMCvusowiF5WVbC4IqO1MAxW7cl3D0Fir8A8PsONkrMtGe-bF4-4oxkCse3M6UCTG1dup_r4jfpJ7ufCUCqzoDT_IHDCM4BVJo8_63yyUdPOZR7qLulCbc6bGODxKtLS07u8IneVwhPPSTmIqtESwC0ux4vav8OGAaFWK0-6_i6nMvyl8lYQGTeVo0tawr6AmBFiim2348IbUUSHl4oFfVCDRN7SLTMqTclNpLfR_7GYu913p7O0h3taS0nSHjqA_Zu4o8Yue0TfO5QtvJPT0OxlOICh Jan 27 22:22:26 volumio volumio[27932]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:22:26 volumio volumio[27932]: info: New Spotify access token = BQCqm4hFtWrs4W0KGpO-E9oh-1smLMCvusowiF5WVbC4IqO1MAxW7cl3D0Fir8A8PsONkrMtGe-bF4-4oxkCse3M6UCTG1dup_r4jfpJ7ufCUCqzoDT_IHDCM4BVJo8_63yyUdPOZR7qLulCbc6bGODxKtLS07u8IneVwhPPSTmIqtESwC0ux4vav8OGAaFWK0-6_i6nMvyl8lYQGTeVo0tawr6AmBFiim2348IbUUSHl4oFfVCDRN7SLTMqTclNpLfR_7GYu913p7O0h3taS0nSHjqA_Zu4o8Yue0TfO5QtvJPT0OxlOICh Jan 27 22:22:26 volumio volumio[27932]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+07:00" level=debug msg="obtained new client token: AABGlEupMilQMeFBZaKZs19HOlMVTPPU62nUfiy+WS/JKPifwR0OaAAxdXV02NzbDDcHoSKOjjON1fdm6YV9LaVUDY1Ey41gvzgikehkrdam2+O2jOED+pfO9J0Abm8XyvG+VDO4yp7s9JTWHIFuq7prNPH+DVNKGtV4OatP71/mffgghNBNYTCLOLm34O+JCLVrQZihPNco8nkP1xxccAlFdaaaF2csH3n7x6mZvmOiQyJ45edzUyu9R8s=" Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio volumio[27932]: info: Starting Shairport Sync Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:27 volumio sudo[28212]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28212]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:27 volumio sudo[28214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:22:27 volumio sudo[28216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio sudo[28214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:27 volumio go-librespot[28194]: time="2026-01-27T22:22:27+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:27 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 22:22:27 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 22:22:27 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:22:27 volumio systemd[1]: shairport-sync.service: Consumed 2.342s CPU time. Jan 27 22:22:27 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:22:27 volumio sudo[28212]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio sudo[28216]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio sudo[28214]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:27 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: Error adding Membership: Error: addMembership EINVAL Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: info: Shairport-Sync Started Jan 27 22:22:27 volumio volumio[27932]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 27 22:22:27 volumio volumio[27932]: info: Spotify Successfully logged in Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:22:27 volumio volumio[27932]: info: [1769527347842] CoreMusicLibrary::Adding element Spotify Jan 27 22:22:27 volumio volumio[27932]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:22:27 volumio volumio[27932]: Cannot find translation for source YouTube Music Jan 27 22:22:27 volumio volumio[27932]: Cannot find translation for source Spotify Jan 27 22:22:28 volumio volumio[27932]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:22:28 volumio volumio[27932]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioGetState Jan 27 22:22:28 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:28 volumio volumio[27932]: info: CoreStateMachine::pushState Jan 27 22:22:28 volumio volumio[27932]: info: CorePlayQueue::getTrack 0 Jan 27 22:22:28 volumio volumio[27932]: info: CoreCommandRouter::volumioPushState Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:29 volumio volumio[27932]: info: go-librespot daemon successfully initialized Jan 27 22:22:30 volumio mpd[28156]: 2026-01-27T22:22:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 22:22:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 22:22:30 volumio sudo[28129]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:30 volumio sudo[28118]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:30 volumio volumio[27932]: error: MPD error: The expression evaluated to a falsy value: Jan 27 22:22:30 volumio volumio[27932]: assert.ok(self.idling) Jan 27 22:22:30 volumio volumio[27932]: error: The expression evaluated to a falsy value: Jan 27 22:22:30 volumio volumio[27932]: assert.ok(self.idling) Jan 27 22:22:30 volumio volumio[27932]: error: updateQueue error: null Jan 27 22:22:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 22:22:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:30 volumio volumio[27932]: info: MPD running with PID28156 Jan 27 22:22:30 volumio volumio[27932]: ,establishing connection Jan 27 22:22:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:30 volumio go-librespot[28255]: go-librespot daemon starting... Jan 27 22:22:30 volumio volumio[27932]: info: Completed starting Core Plugins Jan 27 22:22:30 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:30 volumio volumio[27932]: info: ----- MyVolumio plugins startup ---- Jan 27 22:22:30 volumio volumio[27932]: info: ------------------------------------------- Jan 27 22:22:30 volumio volumio[27932]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=debug msg="app state loaded" Jan 27 22:22:30 volumio go-librespot[28256]: time="2026-01-27T22:22:30+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:30 volumio volumio[27932]: error: updateQueue error: null Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=info msg="zeroconf server listening on port 37619" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="obtained new client token: AABJzjw8GE8bGs6l0sI+tHYzvLlqNUEcuoJUWQQn9CNi4WGSc4aLGMQOAHOFrteEYd5BL6dJRvl6nONJfywUrtbGzDliuZziY+AksmMCPOY3p8zJVc9uk7cWV71CrWMzbSTVjMkLElKym8fG1hORULTgmOeFVlUYNWkEVXI/i+IBUjTRQPQk68MhqHsNPBQb+TtjpB7CH7Rjaf2sr54zCltouUh7hIFOSUFuewi6Zlq7O8r4IYtl3xr9iNU=" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=debug msg="completed challenge" Jan 27 22:22:31 volumio go-librespot[28256]: time="2026-01-27T22:22:31+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:32 volumio volumio[27932]: info: Initializing connection to go-librespot Websocket Jan 27 22:22:32 volumio volumio[27932]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 22:22:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:35 volumio go-librespot[28264]: go-librespot daemon starting... Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="app state loaded" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:35 volumio volumio[27932]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=info msg="zeroconf server listening on port 34689" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="obtained new client token: AADmHc5c/DOwcFHhjf3j3n20pRZSoSV4AcFDFytiQLAXDcFyc6Zpn0OymCqmleXTUiG+1KalLDduIgXL9iSKJ4jsm6zNRYWOi0mH5WZyXv8mVQd/Tq6zOhx9RJQCAdctiDK4avihoqpFflYaMKD9PpfWWulx2ENr1XVqbGjHY8lwsRKBpizuFocEz5UEGNm/zf3LWyryXATI1UwX8PE50WreLREY4EvKLfoYHutCotEv7vr8rg7XyuVg8XM=" Jan 27 22:22:35 volumio go-librespot[28265]: time="2026-01-27T22:22:35+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:35 volumio volumio[27932]: info: Initializing connection to go-librespot Websocket Jan 27 22:22:36 volumio go-librespot[28265]: time="2026-01-27T22:22:36+07:00" level=debug msg="new websocket client" Jan 27 22:22:36 volumio volumio[27932]: info: Connection to go-librespot Websocket established Jan 27 22:22:36 volumio go-librespot[28265]: time="2026-01-27T22:22:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:36 volumio volumio[27932]: info: Connection to go-librespot Websocket closed Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:39 volumio volumio[27932]: info: Getting Spotify volume Jan 27 22:22:39 volumio volumio[27932]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:22:39 volumio volumio[27932]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:22:39 volumio volumio[27932]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 27 22:22:39 volumio volumio[27932]: errno: -111, Jan 27 22:22:39 volumio volumio[27932]: code: 'ECONNREFUSED', Jan 27 22:22:39 volumio volumio[27932]: syscall: 'connect', Jan 27 22:22:39 volumio volumio[27932]: address: '127.0.0.1', Jan 27 22:22:39 volumio volumio[27932]: port: 9879, Jan 27 22:22:39 volumio volumio[27932]: response: undefined Jan 27 22:22:39 volumio volumio[27932]: } Jan 27 22:22:39 volumio volumio[27932]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 22:22:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:39 volumio go-librespot[28284]: go-librespot daemon starting... Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=debug msg="app state loaded" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:39 volumio go-librespot[28285]: time="2026-01-27T22:22:39+07:00" level=info msg="zeroconf server listening on port 40331" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22:40+07:00" level=debug msg="obtained new client token: AAA+sZ52Rh2ZsXQDrYGGY9L0OXHfYGNCrjNqA/U7FD+G07TrujRWP3Z36H2BTOlpKCzJ6zoZ4eBuBT4LLyl4ss4I7ek+mzWgC0RrCWk2D1gsr2loRt2OHzEMQEnhh62ZDYV5u/w4Uwe/WhhHfw5G6fzroeI7LKb260ZIgvz7Wu0bbkkOvZlsrAjR3keAU7Pm/Lxg+EeLYkH8Q7XGrLZMo6kYhdDNiDWGyBKEeE7yQ5YYwvEexI5W1QLr" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22:40+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:40 volumio go-librespot[28285]: time="2026-01-27T22:22:40+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:40 volumio sudo[28309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:21' Jan 27 22:22:40 volumio sudo[28309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:40 volumio sudo[28309]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:42 volumio volumio-remote-updater[628]: [2026-01-27 22:22:42] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 27 22:22:42 volumio volumio-remote-updater[628]: [2026-01-27 22:22:42] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 27 22:22:42 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:42 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 27 22:22:42 volumio systemd[1]: volumio.service: Consumed 52.937s CPU time. Jan 27 22:22:42 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:42 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:42 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 9234. Jan 27 22:22:42 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 27 22:22:42 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 27 22:22:42 volumio systemd[1]: volumio.service: Consumed 52.937s CPU time. Jan 27 22:22:42 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 27 22:22:42 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 27 22:22:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 22:22:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:43 volumio go-librespot[28343]: go-librespot daemon starting... Jan 27 22:22:43 volumio go-librespot[28344]: time="2026-01-27T22:22:43+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:43 volumio go-librespot[28344]: time="2026-01-27T22:22:43+07:00" level=debug msg="app state loaded" Jan 27 22:22:43 volumio go-librespot[28344]: time="2026-01-27T22:22:43+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=info msg="zeroconf server listening on port 34555" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="obtained new client token: AABuTXXaFGgvZYb5deGgmsZX145iHsdYJGoL665KrjWfblhhysu2v26mJrj08J67akpVHTpSXZiqhRz/WXKxRuPjNl6GdO2TIluIrCFC2+bBpi1Ipa88EYXoM/MLfE8hCl+I+3rB5A51qVS1rQqSkr1slM4YUJRZMwp8xsKrDRFDHP10ItIzypS7vzD4q/PV3YugkJRfyqypJaFb+HuwxUxe90go9SgQRQlv5oftRRUvODVjE/d1xQ9p+OY=" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=debug msg="completed challenge" Jan 27 22:22:44 volumio go-librespot[28344]: time="2026-01-27T22:22:44+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:46 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:22:46 volumio volumio[28328]: info: ----- Volumio3 ---- Jan 27 22:22:46 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:22:46 volumio volumio[28328]: info: ----- System startup ---- Jan 27 22:22:46 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:22:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:47 volumio volumio-remote-updater[628]: [2026-01-27 22:22:47] [connect] Successful connection Jan 27 22:22:47 volumio volumio[28328]: info: MYVOLUMIO Environment detected Jan 27 22:22:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 27 22:22:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:47 volumio volumio[28328]: info: Plugin folders cleanup Jan 27 22:22:47 volumio volumio[28328]: info: Scanning into folder /volumio/app/plugins/ Jan 27 22:22:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category audio_interface Jan 27 22:22:47 volumio go-librespot[28360]: go-librespot daemon starting... Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category miscellanea Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category music_service Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category plugins.json Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category system_controller Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category user_interface Jan 27 22:22:47 volumio volumio[28328]: info: Scanning into folder /data/plugins/ Jan 27 22:22:47 volumio volumio[28328]: info: Scanning category music_service Jan 27 22:22:47 volumio volumio[28328]: info: Plugin folders cleanup completed Jan 27 22:22:47 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:22:47 volumio volumio[28328]: info: ----- Core plugins startup ---- Jan 27 22:22:47 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:22:47 volumio volumio[28328]: info: Loading plugins from folder /volumio/app/plugins/ Jan 27 22:22:47 volumio go-librespot[28361]: time="2026-01-27T22:22:47+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:47 volumio go-librespot[28361]: time="2026-01-27T22:22:47+07:00" level=debug msg="app state loaded" Jan 27 22:22:47 volumio go-librespot[28361]: time="2026-01-27T22:22:47+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:47 volumio volumio[28328]: info: Adding plugin upnp to MyMusic Plugins Jan 27 22:22:47 volumio volumio[28328]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 27 22:22:47 volumio volumio[28328]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 27 22:22:47 volumio volumio[28328]: info: Loading plugins from folder /data/plugins/ Jan 27 22:22:47 volumio volumio[28328]: info: Loading plugin "system"... Jan 27 22:22:47 volumio volumio[28328]: info: Loading plugin "appearance"... Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=info msg="zeroconf server listening on port 41597" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=debug msg="obtained new client token: AADTFRsMLogke4wx0H90Djl4NzFkWxPtJMxPLIUBLymwYU9slYxAIzgltMMn3i7DcD50iZkj97RnW5makDaCit+sGNRAr3wGr8z+8AsRqw+MKXxXGiiQHs17CE1Hbh1csMZDVI+cEo2Tlqsk2641dGH+T6YMEjAPR/cBCgno7I+4DL1prbAuzgSAzjiT2ipq8pRnvxxEGw9Mu9FEeDHCw+VNEiLbuWLXwYV3yQHweVJ0FoOhNHMjDPRoMMY=" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:48 volumio go-librespot[28361]: time="2026-01-27T22:22:48+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:49 volumio volumio[28328]: info: Loading plugin "network"... Jan 27 22:22:49 volumio volumio[28328]: info: Refreshing Cached IP Addresses Jan 27 22:22:49 volumio sudo[28373]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:22:49 volumio sudo[28373]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:49 volumio sudo[28373]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:49 volumio sudo[28375]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:22:49 volumio sudo[28375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "services"... Jan 27 22:22:50 volumio sudo[28375]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "alsa_controller"... Jan 27 22:22:50 volumio sudo[28383]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 27 22:22:50 volumio sudo[28383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:22:50 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "wizard"... Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "networkfs"... Jan 27 22:22:50 volumio volumio[28328]: info: Starting Udev Watcher for removable devices Jan 27 22:22:50 volumio volumio[28328]: info: Ignoring mount for partition: boot Jan 27 22:22:50 volumio volumio[28328]: info: Ignoring mount for partition: volumio Jan 27 22:22:50 volumio volumio[28328]: info: Ignoring mount for partition: volumio_data Jan 27 22:22:50 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "volumio_command_line_client"... Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "upnp"... Jan 27 22:22:50 volumio volumio[28328]: info: [1769527370321] Starting Upmpd Daemon Jan 27 22:22:50 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "my_music"... Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "mpd"... Jan 27 22:22:50 volumio volumio[28328]: info: Loading plugin "upnp_browser"... Jan 27 22:22:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 27 22:22:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:52 volumio go-librespot[28406]: go-librespot daemon starting... Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=debug msg="app state loaded" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=info msg="zeroconf server listening on port 32827" Jan 27 22:22:52 volumio sudo[28383]: pam_unix(sudo:session): session closed for user root Jan 27 22:22:52 volumio go-librespot[28407]: time="2026-01-27T22:22:52+07:00" level=debug msg="obtained new client token: AAANYA2p8HI6+q5xA8WzY4q6P2wPz+JQBJpvJayZaYqo4JTf+pB/ZHVwE0nIG2cu4eeGWrCzoJZejzgEUu/BTn/a+68q24y7qQbrVAdvc6U7jWHdfgD+zbmGRMeAVZAKMRnPKV/LQQivf/OGpyUX2hwZmJJhsodZAEChPyVb6q9mbKpd+JKq7p5aia6q/QAEk8TMPTDaMzcNTJE8s3NkdotnQuFVgSCUoRHDmCP41tB9bvS54EfeekbNP0U=" Jan 27 22:22:53 volumio go-librespot[28407]: time="2026-01-27T22:22:53+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:53 volumio go-librespot[28407]: time="2026-01-27T22:22:53+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:22:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:53 volumio volumio[28328]: info: Starting UPNP Browser Jan 27 22:22:53 volumio volumio[28328]: info: Loading plugin "alarm-clock"... Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "airplay_emulation"... Jan 27 22:22:54 volumio volumio[28328]: info: Starting Shairport Sync Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "last_100"... Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "webradio"... Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "i2s_dacs"... Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "volumiodiscovery"... Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:54 volumio node[28328]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** For more information see Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:54 volumio volumio[28328]: *** WARNING *** For more information see Jan 27 22:22:54 volumio node[28328]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:54 volumio node[28328]: *** WARNING *** For more information see Jan 27 22:22:54 volumio node[28328]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 27 22:22:54 volumio node[28328]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 27 22:22:54 volumio node[28328]: *** WARNING *** For more information see Jan 27 22:22:54 volumio volumio[28328]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 27 22:22:54 volumio volumio[28328]: info: Discovery: Started advertising with name: Volumio Jan 27 22:22:54 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 27 22:22:54 volumio volumio[28328]: info: Loading plugin "spop"... Jan 27 22:22:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 27 22:22:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:22:56 volumio go-librespot[28417]: go-librespot daemon starting... Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=debug msg="app state loaded" Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:22:56 volumio volumio[28328]: info: Loading plugin "ytcr"... Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:22:56 volumio go-librespot[28418]: time="2026-01-27T22:22:56+07:00" level=info msg="zeroconf server listening on port 46059" Jan 27 22:22:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:57 volumio go-librespot[28418]: time="2026-01-27T22:22:57+07:00" level=debug msg="obtained new client token: AABfA1zATBcqo/sXbyAU+vtkNVpVwLw+TCeYpPSM9FD9OBuHaiWXm2Tqa/qBCQOrGonZi2eQWPnecB+pXynjZYz0I4Ni0ISHPB4orrMsoq5Po8dZVbxODDpx5OT/wsP4MET4b7GL4ZZkTCYn/1zOvvm/rjrWKodm8OJDKzk9NXQPOyCRXdZmODgGxjwcGr8vutMfzAUQaAbIJm4q3F+AZg3Sfoy0qg0GOTg/g55sMZNOBX09nEHBqV2w" Jan 27 22:22:57 volumio go-librespot[28418]: time="2026-01-27T22:22:57+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:22:57 volumio go-librespot[28418]: time="2026-01-27T22:22:57+07:00" level=debug msg="completed keyexchange" Jan 27 22:22:57 volumio go-librespot[28418]: time="2026-01-27T22:22:57+07:00" level=debug msg="completed challenge" Jan 27 22:22:57 volumio go-librespot[28418]: time="2026-01-27T22:22:57+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:22:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:22:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:22:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:22:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:22:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:22:59 volumio volumio[28328]: info: Loading plugin "ytmusic"... Jan 27 22:22:59 volumio volumio-remote-updater[628]: [2026-01-27 22:22:59] [connect] Successful connection Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "outputs"... Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "albumart"... Jan 27 22:23:00 volumio volumio[28328]: info: Plugin example_plugin is not enabled Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "inputs"... Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "updater_comm"... Jan 27 22:23:00 volumio volumio[28328]: info: Plugin mpdemulation is not enabled Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "rest_api"... Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "websocket"... Jan 27 22:23:00 volumio volumio[28328]: info: Starting Socket.io Server version 1.7.4 Jan 27 22:23:00 volumio volumio[28328]: info: Loading plugin "RoonBridge"... Jan 27 22:23:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 27 22:23:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:00 volumio go-librespot[28451]: go-librespot daemon starting... Jan 27 22:23:00 volumio go-librespot[28452]: time="2026-01-27T22:23:00+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:00 volumio go-librespot[28452]: time="2026-01-27T22:23:00+07:00" level=debug msg="app state loaded" Jan 27 22:23:00 volumio go-librespot[28452]: time="2026-01-27T22:23:00+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:01 volumio volumio[28328]: info: Applying required configuration parameters for plugin RoonBridge Jan 27 22:23:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:01 volumio volumio[28328]: info: Loading i18n strings for locale en Jan 27 22:23:01 volumio volumio[28328]: Updating browse sources language Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=info msg="zeroconf server listening on port 46355" Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::initPlayerControls Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:23:01 volumio volumio[28328]: Express server listening on port 3000 Jan 27 22:23:01 volumio volumio[28328]: [Metrics] WebUI: 16s 126.26ms Jan 27 22:23:01 volumio volumio[28328]: info: CoreStateMachine::resetVolumioState Jan 27 22:23:01 volumio volumio[28328]: info: CoreStateMachine::getcurrentVolume Jan 27 22:23:01 volumio volumio[28328]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:23:01 volumio volumio[28441]: Forking 3 albumart workers Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=debug msg="obtained new client token: AADXa6wR4CbAoY1gYsQrFtIi28GVSQtV5LENkAwaD7WKMOVajv+5tiiWUoWhcYOiWR2eGlvxXm2pFdqk8DQIu5U9o5qsnREmH/TfaTXMXDGqZlr8IIIzUlRK28o+rLpiH/MrqJNENpjoztcwvJvVC3FKdXwBtdbhY1lavPIzOCOq9Pw8+GegHcDXXxlKOU0NU0c1aC18d/x+U5VK1Sy5jZ8rRilCoWUq4i2E7uFJY8KFDdjvbvnXJBYqM8U=" Jan 27 22:23:01 volumio sudo[28470]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 27 22:23:01 volumio sudo[28470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:01 volumio sudo[28467]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 27 22:23:01 volumio sudo[28470]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:01 volumio sudo[28467]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:01 volumio sudo[28467]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:01 volumio volumio[28328]: info: Volumio Network Manager: Network status updated: 1 Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 27 22:23:01 volumio go-librespot[28452]: time="2026-01-27T22:23:01+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 27 22:23:02 volumio go-librespot[28452]: time="2026-01-27T22:23:02+07:00" level=debug msg="completed keyexchange" Jan 27 22:23:02 volumio go-librespot[28452]: time="2026-01-27T22:23:02+07:00" level=debug msg="completed challenge" Jan 27 22:23:02 volumio go-librespot[28452]: time="2026-01-27T22:23:02+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:23:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:02 volumio volumio-remote-updater[628]: [2026-01-27 22:23:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769527379 101 Jan 27 22:23:02 volumio volumio[28328]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 27 22:23:02 volumio volumio[28328]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::pushState Jan 27 22:23:02 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioPushState Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::updateTrackBlock Jan 27 22:23:02 volumio volumio[28328]: info: CorePlayQueue::getTrackBlock Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:02 volumio volumio[28328]: info: Reloading queue from file Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::setRepeat null single undefined Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::pushState Jan 27 22:23:02 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioPushState Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::setRandom null Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::pushState Jan 27 22:23:02 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioPushState Jan 27 22:23:02 volumio volumio[28328]: info: Setting Device type: Raspberry PI Jan 27 22:23:02 volumio volumio[28328]: info: Completed loading Core Plugins Jan 27 22:23:02 volumio volumio[28328]: info: Preparing to generate the ALSA configuration file Jan 27 22:23:02 volumio volumio[28328]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:23:02 volumio volumio[28328]: info: CoreStateMachine::pushState Jan 27 22:23:02 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioPushState Jan 27 22:23:02 volumio volumio[28328]: info: Asound.conf file unchanged, so no further update is needed Jan 27 22:23:02 volumio volumio[28328]: info: Output device has changed, restarting MPD Jan 27 22:23:02 volumio sudo[28511]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 27 22:23:02 volumio volumio[28328]: info: Output device has changed, restarting Shairport Sync Jan 27 22:23:02 volumio sudo[28511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:02 volumio volumio[28328]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:23:02 volumio sudo[28513]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:23:02 volumio volumio[28328]: info: ___________ START PLUGINS ___________ Jan 27 22:23:02 volumio sudo[28515]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:23:02 volumio sudo[28515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:02 volumio sudo[28513]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:02 volumio volumio[28328]: info: ControllerMpd::onStart: Initializing MPD Jan 27 22:23:02 volumio volumio[28328]: info: Creating MPD Configuration file Jan 27 22:23:02 volumio sudo[28513]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:02 volumio sudo[28511]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:23:02 volumio volumio[28328]: info: [1769527382840] CoreMusicLibrary::Adding element Media Servers Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:02 volumio volumio[28328]: info: UPNP Browser: Client initialized successfully Jan 27 22:23:02 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:02 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:02 volumio sudo[28526]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 27 22:23:02 volumio sudo[28526]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:02 volumio sudo[28524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 27 22:23:02 volumio sudo[28524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:03 volumio sudo[28524]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:03 volumio volumio[28328]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:03 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:23:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:23:03 volumio systemd[1]: mpd.service: Consumed 7.394s CPU time. Jan 27 22:23:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:23:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:23:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:23:03 volumio volumio[28328]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:23:03 volumio volumio[28328]: info: [1769527383115] CoreMusicLibrary::Adding element Last_100 Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:23:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:23:03 volumio volumio[28328]: info: [1769527383155] CoreMusicLibrary::Adding element Webradio Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:23:03 volumio volumio[28328]: info: Initializing BBC Radios Jan 27 22:23:03 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 27 22:23:03 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 27 22:23:03 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 27 22:23:03 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 27 22:23:03 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 27 22:23:03 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 27 22:23:03 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:03 volumio volumio[28328]: info: Creating Spotify config file Jan 27 22:23:03 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:03 volumio sudo[28544]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 27 22:23:03 volumio sudo[28544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 27 22:23:03 volumio sudo[28544]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:04 volumio volumio[28328]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:23:04 volumio volumio[28328]: info: [1769527384584] CoreMusicLibrary::Adding element YouTube Music Jan 27 22:23:04 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:04 volumio volumio[28328]: Cannot find translation for source YouTube Music Jan 27 22:23:04 volumio volumio[28328]: info: Volumio Calling Home Jan 27 22:23:04 volumio sudo[28558]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 27 22:23:04 volumio sudo[28558]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:04 volumio volumio[28468]: Starting albumart workers Jan 27 22:23:04 volumio sudo[28558]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:05 volumio volumio[28466]: Starting albumart workers Jan 27 22:23:05 volumio volumio[28464]: Starting albumart workers Jan 27 22:23:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 27 22:23:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:05 volumio go-librespot[28562]: go-librespot daemon starting... Jan 27 22:23:05 volumio go-librespot[28563]: time="2026-01-27T22:23:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:05 volumio volumio[28328]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:23:05 volumio volumio[28328]: info: Discovery: Found device Volumio Jan 27 22:23:05 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:05 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:05 volumio volumio[28328]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 27 22:23:05 volumio volumio[28328]: info: Discovery: Found device Volumio Jan 27 22:23:05 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:05 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:05 volumio volumio[28328]: info: MPD Permissions set Jan 27 22:23:05 volumio volumio[28328]: info: MPD Permissions set Jan 27 22:23:05 volumio volumio[28328]: info: Upmpdcli Daemon Started Jan 27 22:23:05 volumio volumio[28328]: info: Volumio called home Jan 27 22:23:05 volumio volumio[28328]: info: Spotify config file written Jan 27 22:23:06 volumio sudo[28572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 27 22:23:06 volumio sudo[28572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:06 volumio go-librespot[28563]: time="2026-01-27T22:23:06+07:00" level=info msg="zeroconf server listening on port 33695" Jan 27 22:23:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 27 22:23:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 27 22:23:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:06 volumio go-librespot[28575]: go-librespot daemon starting... Jan 27 22:23:06 volumio sudo[28572]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:06 volumio go-librespot[28576]: time="2026-01-27T22:23:06+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:06 volumio go-librespot[28576]: time="2026-01-27T22:23:06+07:00" level=debug msg="app state loaded" Jan 27 22:23:06 volumio go-librespot[28576]: time="2026-01-27T22:23:06+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:06 volumio volumio[28328]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:06 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:07 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 27 22:23:07 volumio volumio[28328]: info: No need to fix Spotify hosts Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=info msg="zeroconf server listening on port 42387" Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=debug msg="obtained new client token: AAB0SPVlfC+g3vn4hWjz6uMmyIHJiDsiFMnwCBgjyZ/wMMcnXxnjTerkUbJTwZyt9bApfM3OAm8Wm5UDVyx+Z2u+j4VFhS1vfScBihsbzB00yPDYjSZa4l4huugfKyxD+lL0G2V7IKPL/vS45kNUnPOd04rsDBKwBjbZHjMntwCAuY63aHjewhstInWGegkwStXuQKs5BnhOh7FoKdDXeIzsZJaUk2+nG1ERUNPxBlCAf+Rywv7vCEDdsa0=" Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:23:07 volumio go-librespot[28576]: time="2026-01-27T22:23:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:23:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:07 volumio volumio[28328]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:23:07 volumio volumio[28328]: SPOTIFY: BQDxOKUpYLVomD_0ahNxWA8KKS9y16b4tHUkOa2qKzqWP0Hfn67HZ_W5hdmuaRMhlzHx34-I5o5Ls31Mhibs8BBnFWPaYScNjaiSnUhIDbcSNGxXT9wq6HgbIqSbuh1LwOCk74aVDM-3nC2c5HtAMDcYlqhnNfyoNevpmBWekCTZcVJN0X56rGIHT1PcVJbnFoarSRFFSkQZym1BxD1Tu7hmH-krggzvb8BZw--KhKmh_aSmozcc-7FffUtLHsF6OMh_QB1WLr3gplPAGT5NcIW1Dc4sn3gQiO4Y_VGjiMAROMGns0QbQFfI Jan 27 22:23:07 volumio volumio[28328]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 27 22:23:07 volumio volumio[28328]: info: New Spotify access token = BQDxOKUpYLVomD_0ahNxWA8KKS9y16b4tHUkOa2qKzqWP0Hfn67HZ_W5hdmuaRMhlzHx34-I5o5Ls31Mhibs8BBnFWPaYScNjaiSnUhIDbcSNGxXT9wq6HgbIqSbuh1LwOCk74aVDM-3nC2c5HtAMDcYlqhnNfyoNevpmBWekCTZcVJN0X56rGIHT1PcVJbnFoarSRFFSkQZym1BxD1Tu7hmH-krggzvb8BZw--KhKmh_aSmozcc-7FffUtLHsF6OMh_QB1WLr3gplPAGT5NcIW1Dc4sn3gQiO4Y_VGjiMAROMGns0QbQFfI Jan 27 22:23:07 volumio volumio[28328]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 27 22:23:07 volumio volumio[28328]: info: Starting Shairport Sync Jan 27 22:23:07 volumio volumio[28328]: info: Starting Shairport Sync Jan 27 22:23:07 volumio volumio[28328]: info: Starting Shairport Sync Jan 27 22:23:07 volumio sudo[28613]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:23:07 volumio sudo[28613]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:08 volumio sudo[28618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:23:08 volumio sudo[28618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:08 volumio sudo[28615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 27 22:23:08 volumio sudo[28615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:08 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 27 22:23:08 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 27 22:23:08 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:23:08 volumio systemd[1]: shairport-sync.service: Consumed 2.247s CPU time. Jan 27 22:23:08 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:08 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:08 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 27 22:23:08 volumio sudo[28615]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:08 volumio sudo[28613]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:08 volumio sudo[28618]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:08 volumio volumio[28328]: info: Shairport-Sync Started Jan 27 22:23:08 volumio volumio[28328]: Error adding Membership: Error: addMembership EINVAL Jan 27 22:23:08 volumio volumio[28328]: info: Shairport-Sync Started Jan 27 22:23:08 volumio volumio[28328]: info: Shairport-Sync Started Jan 27 22:23:08 volumio volumio[28328]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 27 22:23:08 volumio volumio[28328]: info: Spotify Successfully logged in Jan 27 22:23:08 volumio volumio[28328]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 27 22:23:08 volumio volumio[28328]: info: [1769527388615] CoreMusicLibrary::Adding element Spotify Jan 27 22:23:08 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 27 22:23:08 volumio volumio[28328]: Cannot find translation for source YouTube Music Jan 27 22:23:08 volumio volumio[28328]: Cannot find translation for source Spotify Jan 27 22:23:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:09 volumio volumio[28328]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 27 22:23:09 volumio volumio[28328]: info: CoreCommandRouter::volumioRetrievevolume Jan 27 22:23:09 volumio volumio[28328]: info: VolumeController:: Volume=100 Mute =false Jan 27 22:23:09 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:09 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:09 volumio volumio[28328]: info: CoreStateMachine::pushState Jan 27 22:23:09 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:09 volumio volumio[28328]: info: CoreCommandRouter::volumioPushState Jan 27 22:23:10 volumio volumio[28328]: info: go-librespot daemon successfully initialized Jan 27 22:23:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 27 22:23:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:11 volumio go-librespot[28652]: go-librespot daemon starting... Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=debug msg="app state loaded" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:11 volumio mpd[28555]: 2026-01-27T22:23:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 27 22:23:11 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 27 22:23:11 volumio sudo[28515]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:11 volumio sudo[28526]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:11 volumio volumio[28328]: error: MPD error: The expression evaluated to a falsy value: Jan 27 22:23:11 volumio volumio[28328]: assert.ok(self.idling) Jan 27 22:23:11 volumio volumio[28328]: error: The expression evaluated to a falsy value: Jan 27 22:23:11 volumio volumio[28328]: assert.ok(self.idling) Jan 27 22:23:11 volumio volumio[28328]: error: updateQueue error: null Jan 27 22:23:11 volumio volumio[28328]: info: MPD running with PID28555 Jan 27 22:23:11 volumio volumio[28328]: ,establishing connection Jan 27 22:23:11 volumio volumio[28328]: info: Completed starting Core Plugins Jan 27 22:23:11 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:23:11 volumio volumio[28328]: info: ----- MyVolumio plugins startup ---- Jan 27 22:23:11 volumio volumio[28328]: info: ------------------------------------------- Jan 27 22:23:11 volumio volumio[28328]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:23:11 volumio volumio[28328]: error: updateQueue error: null Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=info msg="zeroconf server listening on port 45693" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=debug msg="obtained new client token: AABy3gvHurXMvmdismqSvbO6zcX9TR2q4At9453YgKOf0iL7xDTRrA+/zg1zcSdYN7pdJyKs0p+ro5IzbBRJP8nucz40SdBet0jFYYeYwgh5gupHAxu7pNj4BmSXKPQNeDedW7JPYesMWy8dLJsHE0fdLBF4NTPL1ASiV7mYaaea6Emr+kcB/e1PrNiOriAf/GoDNG6fC/Zv2u5pdHkps5c5G2eLNAuCFshoSO2D6bpqrpgcBeHYixwlXKQ=" Jan 27 22:23:11 volumio go-librespot[28653]: time="2026-01-27T22:23:11+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:23:12 volumio go-librespot[28653]: time="2026-01-27T22:23:12+07:00" level=debug msg="completed keyexchange" Jan 27 22:23:12 volumio go-librespot[28653]: time="2026-01-27T22:23:12+07:00" level=debug msg="completed challenge" Jan 27 22:23:12 volumio go-librespot[28653]: time="2026-01-27T22:23:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:23:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:13 volumio volumio[28328]: info: Initializing connection to go-librespot Websocket Jan 27 22:23:13 volumio volumio[28328]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:23:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 27 22:23:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:15 volumio go-librespot[28664]: go-librespot daemon starting... Jan 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23:15+07:00" level=debug msg="app state loaded" Jan 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23: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 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23: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 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23: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 27 22:23:15 volumio go-librespot[28665]: time="2026-01-27T22:23:15+07:00" level=info msg="zeroconf server listening on port 43565" Jan 27 22:23:16 volumio go-librespot[28665]: time="2026-01-27T22:23:16+07:00" level=debug msg="obtained new client token: AAAysMKH1w27f9Hlq+ZJi3IB0l7OO7V3iB9EuqDc5VUqXu9777Dg4cZRdCuKp4mVYONu1n0DK0oDDHnV/vVRm58XY11cq30mwKWICgzLQbBPQCgc9Qz+EskJCGk0ACMNqeuEv8Xan+wM12T7kAonbuyqKoR4EfnGRfTKl6NFzHyluELgLE3ufI592NNA3/GidXwfDpDuYonkeBngK29ftEL2j7mO49L7mC6jNFw8uaJ+UkbT8R24ImGPmog=" Jan 27 22:23:16 volumio go-librespot[28665]: time="2026-01-27T22:23:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:23:16 volumio go-librespot[28665]: time="2026-01-27T22:23:16+07:00" level=debug msg="completed keyexchange" Jan 27 22:23:16 volumio go-librespot[28665]: time="2026-01-27T22:23:16+07:00" level=debug msg="completed challenge" Jan 27 22:23:16 volumio volumio[28328]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 27 22:23:16 volumio go-librespot[28665]: time="2026-01-27T22:23:16+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:23:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:16 volumio volumio[28328]: info: Initializing connection to go-librespot Websocket Jan 27 22:23:16 volumio volumio[28328]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 27 22:23:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 27 22:23:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:19 volumio go-librespot[28673]: go-librespot daemon starting... Jan 27 22:23:19 volumio go-librespot[28674]: time="2026-01-27T22:23:19+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:19 volumio go-librespot[28674]: time="2026-01-27T22:23:19+07:00" level=debug msg="app state loaded" Jan 27 22:23:19 volumio go-librespot[28674]: time="2026-01-27T22:23:19+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:19 volumio volumio[28328]: info: Initializing connection to go-librespot Websocket Jan 27 22:23:19 volumio go-librespot[28674]: time="2026-01-27T22:23:19+07:00" level=debug msg="new websocket client" Jan 27 22:23:19 volumio volumio[28328]: info: Connection to go-librespot Websocket established Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23: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-gew4.spotify.com:80]" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=info msg="zeroconf server listening on port 41099" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=debug msg="obtained new client token: AABDHgVB9zeMX5BoggIcsipwujn2VPEBSwbtro6944zpl1L5IovWsnTg2B1RtpoDwVe4SQvYgGRkLUtPJ1uT0QR4BX5mJWXE/8xAoi61WXPAsVGLPpRDG3aG93B14FpR+pxuqLRJcE4tRAGTtoSN6KdM0HEHYIsFJ8Ve9K1kSBXeSZOI5z15oDwInm/dqNurn5lMNQhZJhbaPx/OYrtRqGD18pdY6SQqKjAbXhXjVIZy3rwgVhZ26udJXQ4=" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:23:20 volumio go-librespot[28674]: time="2026-01-27T22:23:20+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 27 22:23:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:20 volumio volumio[28328]: info: Connection to go-librespot Websocket closed Jan 27 22:23:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin bluetooth to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin multiroom to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin metavolumio to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin cd_controller to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 27 22:23:20 volumio volumio[28328]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 27 22:23:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:22 volumio volumio[28328]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 27 22:23:22 volumio volumio[28328]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 27 22:23:22 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:22 volumio volumio[28328]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 27 22:23:22 volumio volumio[28328]: info: Starting MyVolumio Remote Streaming Endpoints Jan 27 22:23:22 volumio volumio[28328]: info: MyVolumio login type: Token Jan 27 22:23:22 volumio volumio[28328]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 27 22:23:22 volumio volumio[28328]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 27 22:23:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 27 22:23:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 27 22:23:23 volumio go-librespot[28696]: go-librespot daemon starting... Jan 27 22:23:23 volumio go-librespot[28697]: time="2026-01-27T22:23:23+07:00" level=info msg="running go-librespot 0.4.0" Jan 27 22:23:23 volumio go-librespot[28697]: time="2026-01-27T22:23:23+07:00" level=debug msg="app state loaded" Jan 27 22:23:23 volumio go-librespot[28697]: time="2026-01-27T22:23:23+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 27 22:23:24 volumio volumio[28328]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 27 22:23:24 volumio volumio[28328]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 27 22:23:24 volumio volumio[28328]: info: Streaming services startup Jan 27 22:23:24 volumio volumio[28328]: info: Starting Streaming Daemon Jan 27 22:23:24 volumio sudo[28705]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 27 22:23:24 volumio sudo[28705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 22:23:24 volumio volumio[28328]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 27 22:23:24 volumio sudo[28705]: pam_unix(sudo:session): session closed for user root Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=info msg="zeroconf server listening on port 39121" Jan 27 22:23:24 volumio volumio[28328]: info: Getting Spotify volume Jan 27 22:23:24 volumio volumio[28328]: info: Initializing connection to go-librespot Websocket Jan 27 22:23:24 volumio volumio[28328]: error: Cannot start Volumio Streaming Daemon Jan 27 22:23:24 volumio volumio[28328]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 27 22:23:24 volumio volumio[28328]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="new websocket client" Jan 27 22:23:24 volumio volumio[28328]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 27 22:23:24 volumio volumio[28328]: info: Connection to go-librespot Websocket established Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="obtained new client token: AADou3UeTupGWOpgUZwwPknvwUwocQOy/uB1jVFW3WSM8vOcblYCGFQJGZ2MUC1Yy2V5eba7rRyjPqB9IxYpt9sCtqV1y+DsOPBjcVGiwoIOeSy7CqqUIxBWTBDUruM4emICQH+9Lwl1KtPKTG9hSx3U1IdD/AajTqB+dJp5y49pViAk5vhOsRR96mndELsP2+BhY6kLSwzez5JVOi8zjD/vUzzrgAymYaTVQb18ELoz3gmsy06JB+CiZqE=" Jan 27 22:23:24 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:24 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:24 volumio volumio[28328]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 22:23:24 volumio volumio[28328]: SPOTIFY: SPOTIFY VOLUME undefined Jan 27 22:23:24 volumio volumio[28328]: SPOTIFY: VOLUMIO VOLUME 100 Jan 27 22:23:24 volumio volumio[28328]: info: Aligning Spotify Volume to Volumio Volume Jan 27 22:23:24 volumio volumio[28328]: info: CoreCommandRouter::volumioGetState Jan 27 22:23:24 volumio volumio[28328]: info: CorePlayQueue::getTrack 0 Jan 27 22:23:24 volumio volumio[28328]: info: Setting Spotify Volume from Volumio: 100 Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="completed keyexchange" Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=debug msg="completed challenge" Jan 27 22:23:24 volumio go-librespot[28697]: time="2026-01-27T22:23:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 27 22:23:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 27 22:23:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 27 22:23:24 volumio volumio[28328]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:23:24 volumio volumio[28328]: Error: socket hang up Jan 27 22:23:24 volumio volumio[28328]: at connResetException (node:internal/errors:720:14) Jan 27 22:23:24 volumio volumio[28328]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 27 22:23:24 volumio volumio[28328]: at Socket.emit (node:events:526:35) Jan 27 22:23:24 volumio volumio[28328]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 27 22:23:24 volumio volumio[28328]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 27 22:23:24 volumio volumio[28328]: code: 'ECONNRESET', Jan 27 22:23:24 volumio volumio[28328]: response: undefined Jan 27 22:23:24 volumio volumio[28328]: } Jan 27 22:23:25 volumio volumio[28328]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 22:23:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 27 22:23:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 27 22:23:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 27 22:23:26 volumio sudo[28726]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 22:22' Jan 27 22:23:26 volumio sudo[28726]: 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"