Jan 25 22:51:00 volumio volumio[5367]: info: MYVOLUMIO Environment detected Jan 25 22:51:00 volumio volumio[5367]: info: Plugin folders cleanup Jan 25 22:51:00 volumio volumio[5367]: info: Scanning into folder /volumio/app/plugins/ Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category audio_interface Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category miscellanea Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category music_service Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category plugins.json Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category system_controller Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category user_interface Jan 25 22:51:00 volumio volumio[5367]: info: Scanning into folder /data/plugins/ Jan 25 22:51:00 volumio volumio[5367]: info: Scanning category music_service Jan 25 22:51:00 volumio volumio[5367]: info: Plugin folders cleanup completed Jan 25 22:51:00 volumio volumio[5367]: info: ------------------------------------------- Jan 25 22:51:00 volumio volumio[5367]: info: ----- Core plugins startup ---- Jan 25 22:51:00 volumio volumio[5367]: info: ------------------------------------------- Jan 25 22:51:00 volumio volumio[5367]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 22:51:00 volumio volumio[5367]: info: Adding plugin upnp to MyMusic Plugins Jan 25 22:51:00 volumio volumio[5367]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 22:51:00 volumio volumio[5367]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 22:51:00 volumio volumio[5367]: info: Loading plugins from folder /data/plugins/ Jan 25 22:51:00 volumio volumio[5367]: info: Loading plugin "system"... Jan 25 22:51:00 volumio volumio[5367]: info: Loading plugin "appearance"... Jan 25 22:51:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 25 22:51:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:01 volumio go-librespot[5402]: go-librespot daemon starting... Jan 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51:01+07:00" level=debug msg="app state loaded" Jan 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51: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 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51: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 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51: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 25 22:51:01 volumio go-librespot[5403]: time="2026-01-25T22:51:01+07:00" level=info msg="zeroconf server listening on port 35387" Jan 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51:02+07:00" level=debug msg="obtained new client token: AADQE3y75Eba/IvDwibqENw8Dk2Cl5+JjnqlF7ygNYUhhz9MWG3zrRMMi26BWKfFxaTNpWK+XJSW7sFWx4xj3a6yjIzsC5vT5J1YsIA32ugJ6+y/cUqVJPHEGft5k9eGF7GTgYsBLWRhQtfu4UR7IzIowlbLoH0GSB2bFLjjWp0pBw8EAhGUGJM9wxe4gqVfSJawevDbIEZxca+mLOz9XCtLY8AjYiqMTJ9g6vGEi9PstltJSmVCzJ0e" Jan 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51:02+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 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51:02+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "network"... Jan 25 22:51:02 volumio volumio[5367]: info: Refreshing Cached IP Addresses Jan 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51:02+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51:02+07:00" level=debug msg="completed challenge" Jan 25 22:51:02 volumio sudo[5411]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:51:02 volumio sudo[5413]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:51:02 volumio sudo[5413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:02 volumio sudo[5413]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:02 volumio sudo[5411]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "services"... Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "alsa_controller"... Jan 25 22:51:02 volumio sudo[5411]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:02 volumio sudo[5418]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 22:51:02 volumio sudo[5418]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:02 volumio go-librespot[5403]: time="2026-01-25T22:51: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 25 22:51:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:02 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "wizard"... Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "networkfs"... Jan 25 22:51:02 volumio volumio[5367]: info: Starting Udev Watcher for removable devices Jan 25 22:51:02 volumio volumio[5367]: info: Ignoring mount for partition: boot Jan 25 22:51:02 volumio volumio[5367]: info: Ignoring mount for partition: volumio Jan 25 22:51:02 volumio volumio[5367]: info: Ignoring mount for partition: volumio_data Jan 25 22:51:02 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "volumio_command_line_client"... Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "upnp"... Jan 25 22:51:02 volumio volumio[5367]: info: [1769356262736] Starting Upmpd Daemon Jan 25 22:51:02 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "my_music"... Jan 25 22:51:02 volumio volumio[5367]: info: Loading plugin "mpd"... Jan 25 22:51:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:03 volumio volumio[5367]: info: Loading plugin "upnp_browser"... Jan 25 22:51:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:05 volumio sudo[5418]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 25 22:51:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:05 volumio go-librespot[5445]: go-librespot daemon starting... Jan 25 22:51:05 volumio go-librespot[5446]: time="2026-01-25T22:51:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:05 volumio go-librespot[5446]: time="2026-01-25T22:51:05+07:00" level=debug msg="app state loaded" Jan 25 22:51:05 volumio go-librespot[5446]: time="2026-01-25T22:51:05+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=info msg="zeroconf server listening on port 42533" Jan 25 22:51:06 volumio volumio[5367]: info: Starting UPNP Browser Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "alarm-clock"... Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="obtained new client token: AAB6alqqfHgc/A0Qokc1qCSiMQgYIGEDoH27hyiqpRl9qfXlwAYkrAyLF0YgbT+W/ib5NQkNbZeOFXx9vyn0JsAbcjbtsoElCwczJWHJBfpPdWXMxxypol2+qHC5/AZbCbX5dJhk2YOl8T0r789+a0I9xX9CfX+tgeWVkskw3ZR+DflLVBpegYuSqexiZqVb3OzPCdWJ9UUGYIuYDTtBj5aUN1EwG5kheNfBpCvMU1Z4Z2WL32OLpO4EHvs=" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "airplay_emulation"... Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=debug msg="completed challenge" Jan 25 22:51:06 volumio volumio[5367]: info: Starting Shairport Sync Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "last_100"... Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "webradio"... Jan 25 22:51:06 volumio go-librespot[5446]: time="2026-01-25T22:51:06+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "i2s_dacs"... Jan 25 22:51:06 volumio volumio[5367]: info: Loading plugin "volumiodiscovery"... Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** For more information see Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:06 volumio volumio[5367]: *** WARNING *** For more information see Jan 25 22:51:06 volumio node[5367]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:06 volumio node[5367]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:06 volumio node[5367]: *** WARNING *** For more information see Jan 25 22:51:06 volumio node[5367]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:06 volumio node[5367]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:06 volumio node[5367]: *** WARNING *** For more information see Jan 25 22:51:06 volumio volumio[5367]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 22:51:06 volumio volumio[5367]: info: Discovery: Started advertising with name: Volumio Jan 25 22:51:07 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:07 volumio volumio[5367]: info: Loading plugin "spop"... Jan 25 22:51:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:08 volumio volumio[5367]: info: Loading plugin "ytcr"... Jan 25 22:51:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 25 22:51:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:09 volumio go-librespot[5458]: go-librespot daemon starting... Jan 25 22:51:09 volumio go-librespot[5459]: time="2026-01-25T22:51:09+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:09 volumio go-librespot[5459]: time="2026-01-25T22:51:09+07:00" level=debug msg="app state loaded" Jan 25 22:51:09 volumio go-librespot[5459]: time="2026-01-25T22:51:09+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=info msg="zeroconf server listening on port 34601" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="obtained new client token: AAC9KUYAy31bGaMhmGOSttBXpUiKwGWhockvjCnSwjdtC7kzIrJqD//XVGLgYNGlMPsednuLLgFrjl7s7p21PirJQXppS/B+sTkreuw4huAcYC43pL6/rOrfYyrfWVAVlybu9T+FhYQ67f+djgtbg/5lI2xcuFWqSzwyQlhTmvkn3uTrxH02OAEtZvA3tQSapyO26fDSPPacY5QluHa3FwJqKz0APYRW67EVdXkA7/pp5Q3zSrWNQYfaS1k=" Jan 25 22:51:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+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 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:10 volumio go-librespot[5459]: time="2026-01-25T22:51:10+07:00" level=debug msg="completed challenge" Jan 25 22:51:11 volumio go-librespot[5459]: time="2026-01-25T22:51:11+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:11 volumio volumio[5367]: info: Loading plugin "ytmusic"... Jan 25 22:51:12 volumio volumio-remote-updater[628]: [2026-01-25 22:51:12] [connect] Successful connection Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "outputs"... Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "albumart"... Jan 25 22:51:12 volumio volumio[5367]: info: Plugin example_plugin is not enabled Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "inputs"... Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "updater_comm"... Jan 25 22:51:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:12 volumio volumio[5367]: info: Plugin mpdemulation is not enabled Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "rest_api"... Jan 25 22:51:12 volumio volumio[5367]: info: Loading plugin "websocket"... Jan 25 22:51:12 volumio volumio[5367]: info: Starting Socket.io Server version 1.7.4 Jan 25 22:51:13 volumio volumio[5367]: info: Loading plugin "RoonBridge"... Jan 25 22:51:13 volumio volumio[5367]: info: Applying required configuration parameters for plugin RoonBridge Jan 25 22:51:13 volumio volumio[5367]: info: Loading i18n strings for locale en Jan 25 22:51:13 volumio volumio[5367]: Updating browse sources language Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:13 volumio volumio[5480]: Forking 3 albumart workers Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::initPlayerControls Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:13 volumio volumio[5367]: Express server listening on port 3000 Jan 25 22:51:13 volumio volumio[5367]: [Metrics] WebUI: 16s 12.91ms Jan 25 22:51:13 volumio volumio[5367]: info: CoreStateMachine::resetVolumioState Jan 25 22:51:13 volumio volumio[5367]: info: CoreStateMachine::getcurrentVolume Jan 25 22:51:13 volumio volumio[5367]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:51:14 volumio sudo[5524]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:51:14 volumio sudo[5524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:14 volumio sudo[5524]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:14 volumio sudo[5526]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:51:14 volumio sudo[5526]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:14 volumio sudo[5526]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:14 volumio volumio[5367]: info: Volumio Network Manager: Network status updated: 1 Jan 25 22:51:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 25 22:51:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:14 volumio go-librespot[5532]: go-librespot daemon starting... Jan 25 22:51:14 volumio go-librespot[5533]: time="2026-01-25T22:51:14+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:14 volumio go-librespot[5533]: time="2026-01-25T22:51:14+07:00" level=debug msg="app state loaded" Jan 25 22:51:14 volumio go-librespot[5533]: time="2026-01-25T22:51:14+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:14 volumio volumio[5367]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::pushState Jan 25 22:51:14 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::updateTrackBlock Jan 25 22:51:14 volumio volumio[5367]: info: CorePlayQueue::getTrackBlock Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:51:14 volumio volumio-remote-updater[628]: [2026-01-25 22:51:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769356272 101 Jan 25 22:51:14 volumio volumio[5367]: 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 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:14 volumio volumio[5367]: info: Reloading queue from file Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::setRepeat null single undefined Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::pushState Jan 25 22:51:14 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::setRandom null Jan 25 22:51:14 volumio volumio[5367]: info: CoreStateMachine::pushState Jan 25 22:51:14 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:14 volumio volumio[5367]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:14 volumio volumio[5367]: info: Setting Device type: Raspberry PI Jan 25 22:51:14 volumio volumio[5367]: info: Completed loading Core Plugins Jan 25 22:51:14 volumio volumio[5367]: info: Preparing to generate the ALSA configuration file Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+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 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+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 25 22:51:15 volumio volumio[5367]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:51:15 volumio volumio[5367]: info: CoreStateMachine::pushState Jan 25 22:51:15 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=info msg="zeroconf server listening on port 41291" Jan 25 22:51:15 volumio volumio[5367]: info: Asound.conf file unchanged, so no further update is needed Jan 25 22:51:15 volumio volumio[5367]: info: Output device has changed, restarting MPD Jan 25 22:51:15 volumio sudo[5549]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 22:51:15 volumio sudo[5549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:15 volumio volumio[5367]: info: Output device has changed, restarting Shairport Sync Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:15 volumio sudo[5552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:51:15 volumio sudo[5552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:15 volumio sudo[5552]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=debug msg="obtained new client token: AAAQM7c2cCxDz7eDY9YXUanV27wNZ+4iEAAe7+vBAWXSGoDaORFpDrDFIXJq8pNao9y3K0Rdwg5AugV677XE/V0RisyREAXOJPq3JVPACY/iVQFkye2By8uc3ArTUiZ0CF2vbTUC18Phbe7+Mmbc/HGt4p0nkBI3XpxZB276etvUb1f7I4IfXLYEPhwoPWVATWQ1IGOzFudpU/ULi2WSU1Rb7ozmDL1qt3eN3vZ8vXF9O+Kll8+l7GCi" Jan 25 22:51:15 volumio sudo[5549]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:15 volumio sudo[5555]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:51:15 volumio sudo[5555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:15 volumio volumio[5367]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:15 volumio volumio[5367]: info: ___________ START PLUGINS ___________ Jan 25 22:51:15 volumio volumio[5367]: info: ControllerMpd::onStart: Initializing MPD Jan 25 22:51:15 volumio volumio[5367]: info: Creating MPD Configuration file Jan 25 22:51:15 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=debug msg="completed challenge" Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:15 volumio volumio[5367]: info: [1769356275591] CoreMusicLibrary::Adding element Media Servers Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:15 volumio go-librespot[5533]: time="2026-01-25T22:51:15+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:15 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 25 22:51:15 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 22:51:15 volumio systemd[1]: mpd.service: Consumed 7.440s CPU time. Jan 25 22:51:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:15 volumio sudo[5564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:51:15 volumio sudo[5564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:15 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 25 22:51:15 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 22:51:15 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 22:51:15 volumio sudo[5563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:51:15 volumio sudo[5563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:15 volumio volumio[5367]: info: UPNP Browser: Client initialized successfully Jan 25 22:51:15 volumio sudo[5563]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:15 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 22:51:15 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 22:51:15 volumio volumio[5367]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:15 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 25 22:51:15 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:15 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 25 22:51:15 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 22:51:15 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 22:51:15 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 22:51:15 volumio volumio[5367]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:15 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 22:51:15 volumio volumio[5367]: info: [1769356275936] CoreMusicLibrary::Adding element Last_100 Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:15 volumio volumio[5367]: info: [1769356275959] CoreMusicLibrary::Adding element Webradio Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:15 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:16 volumio volumio[5367]: info: Initializing BBC Radios Jan 25 22:51:16 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:16 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:16 volumio volumio[5367]: info: Creating Spotify config file Jan 25 22:51:16 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:16 volumio sudo[5578]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 22:51:16 volumio sudo[5578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 22:51:16 volumio sudo[5578]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:16 volumio volumio[5492]: Starting albumart workers Jan 25 22:51:17 volumio volumio[5491]: Starting albumart workers Jan 25 22:51:17 volumio volumio[5490]: Starting albumart workers Jan 25 22:51:17 volumio volumio[5367]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:17 volumio volumio[5367]: info: [1769356277384] CoreMusicLibrary::Adding element YouTube Music Jan 25 22:51:17 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:17 volumio volumio[5367]: Cannot find translation for source YouTube Music Jan 25 22:51:17 volumio volumio[5367]: info: Volumio Calling Home Jan 25 22:51:17 volumio sudo[5595]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 25 22:51:17 volumio sudo[5595]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:17 volumio sudo[5595]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:18 volumio volumio[5367]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:51:18 volumio volumio[5367]: info: Discovery: Found device Volumio Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:18 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:18 volumio volumio[5367]: info: MPD Permissions set Jan 25 22:51:18 volumio volumio[5367]: info: MPD Permissions set Jan 25 22:51:18 volumio volumio[5367]: info: Upmpdcli Daemon Started Jan 25 22:51:18 volumio volumio[5367]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:51:18 volumio volumio[5367]: info: Discovery: Found device Volumio Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:18 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:18 volumio volumio[5367]: info: Spotify config file written Jan 25 22:51:18 volumio sudo[5601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 22:51:18 volumio sudo[5601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:18 volumio volumio[5367]: 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 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio go-librespot[5603]: go-librespot daemon starting... Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio sudo[5601]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:18 volumio go-librespot[5609]: time="2026-01-25T22:51:18+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:18 volumio go-librespot[5609]: time="2026-01-25T22:51:18+07:00" level=debug msg="app state loaded" Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:18 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:18 volumio go-librespot[5609]: time="2026-01-25T22:51:18+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:18 volumio volumio[5367]: info: No need to fix Spotify hosts Jan 25 22:51:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+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 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+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 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=info msg="zeroconf server listening on port 45009" Jan 25 22:51:19 volumio volumio[5367]: info: Volumio called home Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=debug msg="obtained new client token: AACDNy2M7/XsENEKzQb/LryYtAuichaH7mbbXoV6XW84GT1MXoHsjFFcra1FuF2vsI8f+grov2oombJU5WcSuOdUzCxmSiffLpwFPyJ6KuLOnEE2ed99oQ9gu67CPITz43ntqvU1t0sgoBvy1SoPMb4+oPPkgkE/LZ6zh4Jwh0lIxHKRH7mDYbuSPVe/N/X+vjr0kt7GH2eHBZSJaQ3gjZgIei1YY9/ucEMYTXJZB2GCNCOu0VrT0pNQ7hk=" Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=debug msg="completed challenge" Jan 25 22:51:19 volumio volumio[5367]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:51:19 volumio volumio[5367]: SPOTIFY: BQAYq2RhxbP3pye7Ijw0R9yUaHlUvsmYOCjC_7_H5kZXonuPiQEsAgJlFTs4QHGzD_XuINGX4OArLLqD5xpZe6d-LkfphLphz3sa24P1YX7kVDItkDm-1hGW2RXTNzMplHuA59sctuZgwGBJ65K7hIZR9wQv7_cRZRlBhBYDRL7FFhN7l9sU03KEz6HvXqNuMGzkKx19E-yg-3AsyBdhIuYagnYbAj_dh62yTnQ5gWgpKf2XeHNNk8IsWO2EsvWcjbBs9nBXsIXB7FSJTcXNITAN5BgtgFGOrWn0LUndZKRDMmjfyEd7xUKh Jan 25 22:51:19 volumio volumio[5367]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:51:19 volumio volumio[5367]: info: New Spotify access token = BQAYq2RhxbP3pye7Ijw0R9yUaHlUvsmYOCjC_7_H5kZXonuPiQEsAgJlFTs4QHGzD_XuINGX4OArLLqD5xpZe6d-LkfphLphz3sa24P1YX7kVDItkDm-1hGW2RXTNzMplHuA59sctuZgwGBJ65K7hIZR9wQv7_cRZRlBhBYDRL7FFhN7l9sU03KEz6HvXqNuMGzkKx19E-yg-3AsyBdhIuYagnYbAj_dh62yTnQ5gWgpKf2XeHNNk8IsWO2EsvWcjbBs9nBXsIXB7FSJTcXNITAN5BgtgFGOrWn0LUndZKRDMmjfyEd7xUKh Jan 25 22:51:19 volumio volumio[5367]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 25 22:51:19 volumio go-librespot[5609]: time="2026-01-25T22:51:19+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:20 volumio volumio[5367]: info: Starting Shairport Sync Jan 25 22:51:20 volumio volumio[5367]: info: Starting Shairport Sync Jan 25 22:51:20 volumio volumio[5367]: info: Starting Shairport Sync Jan 25 22:51:20 volumio sudo[5643]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:20 volumio sudo[5643]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:20 volumio sudo[5647]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:20 volumio sudo[5647]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:20 volumio sudo[5645]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:20 volumio sudo[5645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 22:51:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 22:51:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:51:20 volumio systemd[1]: shairport-sync.service: Consumed 2.484s CPU time. Jan 25 22:51:20 volumio volumio[5367]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:20 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:51:20 volumio sudo[5645]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:20 volumio sudo[5643]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:20 volumio sudo[5647]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:20 volumio volumio[5367]: info: Shairport-Sync Started Jan 25 22:51:20 volumio volumio[5367]: Error adding Membership: Error: addMembership EINVAL Jan 25 22:51:20 volumio volumio[5367]: info: Shairport-Sync Started Jan 25 22:51:20 volumio volumio[5367]: info: Shairport-Sync Started Jan 25 22:51:20 volumio volumio[5367]: 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 25 22:51:20 volumio volumio[5367]: info: Spotify Successfully logged in Jan 25 22:51:20 volumio volumio[5367]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:20 volumio volumio[5367]: info: [1769356280794] CoreMusicLibrary::Adding element Spotify Jan 25 22:51:20 volumio volumio[5367]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:20 volumio volumio[5367]: Cannot find translation for source YouTube Music Jan 25 22:51:20 volumio volumio[5367]: Cannot find translation for source Spotify Jan 25 22:51:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:21 volumio volumio[5367]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 25 22:51:21 volumio volumio[5367]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:51:21 volumio volumio[5367]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:51:21 volumio volumio[5367]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:21 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:21 volumio volumio[5367]: info: CoreStateMachine::pushState Jan 25 22:51:21 volumio volumio[5367]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:21 volumio volumio[5367]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:22 volumio volumio[5367]: info: go-librespot daemon successfully initialized Jan 25 22:51:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jan 25 22:51:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:23 volumio go-librespot[5684]: go-librespot daemon starting... Jan 25 22:51:23 volumio go-librespot[5685]: time="2026-01-25T22:51:23+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:23 volumio go-librespot[5685]: time="2026-01-25T22:51:23+07:00" level=debug msg="app state loaded" Jan 25 22:51:23 volumio go-librespot[5685]: time="2026-01-25T22:51:23+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:23 volumio mpd[5593]: 2026-01-25T22:51:23 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 22:51:23 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 22:51:23 volumio sudo[5555]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:23 volumio sudo[5564]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+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 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+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 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+07:00" level=info msg="zeroconf server listening on port 33705" Jan 25 22:51:24 volumio volumio[5367]: error: MPD error: The expression evaluated to a falsy value: Jan 25 22:51:24 volumio volumio[5367]: assert.ok(self.idling) Jan 25 22:51:24 volumio volumio[5367]: error: The expression evaluated to a falsy value: Jan 25 22:51:24 volumio volumio[5367]: assert.ok(self.idling) Jan 25 22:51:24 volumio volumio[5367]: error: updateQueue error: null Jan 25 22:51:24 volumio volumio[5367]: info: MPD running with PID5593 Jan 25 22:51:24 volumio volumio[5367]: ,establishing connection Jan 25 22:51:24 volumio volumio[5367]: info: Completed starting Core Plugins Jan 25 22:51:24 volumio volumio[5367]: info: ------------------------------------------- Jan 25 22:51:24 volumio volumio[5367]: info: ----- MyVolumio plugins startup ---- Jan 25 22:51:24 volumio volumio[5367]: info: ------------------------------------------- Jan 25 22:51:24 volumio volumio[5367]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 22:51:24 volumio volumio[5367]: error: updateQueue error: null Jan 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+07:00" level=debug msg="obtained new client token: AAAbd8i9dmasWI5xVCl/FGJBZa7wDRzP986i+8lNW8BiLr+o40HI1CM+LyP4/wDm5gEhtYBYppkfkkZudiib/nf4UrVU1A9LgcoYrgAoB1E8RI/pU56Vr9QTLmTX1KzbVcwDKUDvQqLNm/VhZYlu++Ubadhv4APgYpK6DJkeczJmeUXCSh/zBS5tZumh5Xfujj1kL+DN4Vsvsmycp69Rti8Gl7BRJk3C+By7qF5/Mnyer2LvsYo4mdjU" Jan 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:24 volumio go-librespot[5685]: time="2026-01-25T22:51:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 25 22:51:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:25 volumio volumio[5367]: info: Initializing connection to go-librespot Websocket Jan 25 22:51:26 volumio volumio[5367]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:51:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 25 22:51:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:27 volumio go-librespot[5696]: go-librespot daemon starting... Jan 25 22:51:27 volumio go-librespot[5697]: time="2026-01-25T22:51:27+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:27 volumio go-librespot[5697]: time="2026-01-25T22:51:27+07:00" level=debug msg="app state loaded" Jan 25 22:51:27 volumio go-librespot[5697]: time="2026-01-25T22:51:27+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+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 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+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 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+07:00" level=info msg="zeroconf server listening on port 38327" Jan 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+07:00" level=debug msg="obtained new client token: AACUY4sAtJ9UcoXHFNNsoem3BygGGBNk64CnkWN34NVciemyZRoVRnOBLCy+olaJO1dd9u0E+G2Ni2+lu65FRczTVEMceCDaX9L6fqaxRQ+HRfotZR+HscCvdBoyadzfOLh83vVCSl5VDteT99zIjBsHFFBQsoiOpl9zJbmjoIZbt8DGmlnj9b+vFsqW9GdAyfVk75Mw4Y/a2mKFepHeJlrOPt3q3krazqUNh/SnPMbIu6l3Y9GMuS7iAeQ=" Jan 25 22:51:28 volumio go-librespot[5697]: time="2026-01-25T22:51:28+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:28 volumio volumio[5367]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 22:51:29 volumio volumio[5367]: info: Initializing connection to go-librespot Websocket Jan 25 22:51:29 volumio go-librespot[5697]: time="2026-01-25T22:51:29+07:00" level=debug msg="new websocket client" Jan 25 22:51:29 volumio volumio[5367]: info: Connection to go-librespot Websocket established Jan 25 22:51:29 volumio go-librespot[5697]: time="2026-01-25T22:51:29+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:29 volumio go-librespot[5697]: time="2026-01-25T22:51:29+07:00" level=debug msg="completed challenge" Jan 25 22:51:29 volumio go-librespot[5697]: time="2026-01-25T22:51:29+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:29 volumio volumio[5367]: info: Connection to go-librespot Websocket closed Jan 25 22:51:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:32 volumio volumio[5367]: info: Getting Spotify volume Jan 25 22:51:32 volumio volumio[5367]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:51:32 volumio volumio[5367]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:51:32 volumio volumio[5367]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 25 22:51:32 volumio volumio[5367]: errno: -111, Jan 25 22:51:32 volumio volumio[5367]: code: 'ECONNREFUSED', Jan 25 22:51:32 volumio volumio[5367]: syscall: 'connect', Jan 25 22:51:32 volumio volumio[5367]: address: '127.0.0.1', Jan 25 22:51:32 volumio volumio[5367]: port: 9879, Jan 25 22:51:32 volumio volumio[5367]: response: undefined Jan 25 22:51:32 volumio volumio[5367]: } Jan 25 22:51:32 volumio volumio[5367]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:51:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Jan 25 22:51:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:33 volumio go-librespot[5730]: go-librespot daemon starting... Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=debug msg="app state loaded" Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:33 volumio sudo[5740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 22:50' Jan 25 22:51:33 volumio sudo[5740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+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 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+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 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=info msg="zeroconf server listening on port 43345" Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=debug msg="obtained new client token: AAB7iV/N7hSbymq5jd+P65lJ8OGhPpPqYRTUmORJcKlWfPqVa3ykxXrZgQDISRMifGzSEucq+A+5LOCQANuIxwhiCJee9ErtCa8PAFxbgNQ9/g8FmT0SnBUyRyJWf5nz+DPE8Rt+9WMS0O+OWjzemPbJOsD3qWKBsmVGy+/ImRPy6moktzYRQaiD7ZtAMmJ9L3/R02fk7QqhUbgRobvM4fN3iwt+KUWsaHHAOxg43FLLAFS9LySgrCSQ12Y=" Jan 25 22:51:33 volumio sudo[5740]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:33 volumio go-librespot[5731]: time="2026-01-25T22:51:33+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:34 volumio volumio-remote-updater[628]: [2026-01-25 22:51:34] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 22:51:34 volumio volumio-remote-updater[628]: [2026-01-25 22:51:34] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 22:51:34 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:34 volumio go-librespot[5731]: time="2026-01-25T22:51:34+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:34 volumio go-librespot[5731]: time="2026-01-25T22:51:34+07:00" level=debug msg="completed challenge" Jan 25 22:51:34 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 22:51:34 volumio systemd[1]: volumio.service: Consumed 56.070s CPU time. Jan 25 22:51:34 volumio go-librespot[5731]: time="2026-01-25T22:51:34+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 25 22:51:34 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 22:51:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:34 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 22:51:34 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6112. Jan 25 22:51:34 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 22:51:34 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 22:51:34 volumio systemd[1]: volumio.service: Consumed 56.070s CPU time. Jan 25 22:51:34 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 22:51:34 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 22:51:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jan 25 22:51:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:37 volumio go-librespot[5774]: go-librespot daemon starting... Jan 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+07:00" level=debug msg="app state loaded" Jan 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:37 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:51:37 volumio volumio[5757]: info: ----- Volumio3 ---- Jan 25 22:51:37 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:51:37 volumio volumio[5757]: info: ----- System startup ---- Jan 25 22:51:37 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+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 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+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 25 22:51:37 volumio go-librespot[5775]: time="2026-01-25T22:51:37+07:00" level=info msg="zeroconf server listening on port 33155" Jan 25 22:51:38 volumio go-librespot[5775]: time="2026-01-25T22:51:38+07:00" level=debug msg="obtained new client token: AACwleZ+AAUt65eohQwRqLIJ/GX6fp2jreX6QM/ylhWL05ry2yJYI+tM+ACTam0MuzCZJoHSDJ9PvHZsmJdAaMckiuS5gtzaGKWHXR8u4o8AmrYdsSQhdNUQw7DocnbTvAF1oUUKOs1OZs9478OwlSvTIY2Z7hTMshQkcFo9DhTlxteQJG4n+TR39TOTIyRd1NKmLGk2dVoef6jVq79yuE8Uf4JkAY4WDX3ZSNZTs0LUk92NTd/48jqe" Jan 25 22:51:38 volumio go-librespot[5775]: time="2026-01-25T22:51:38+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:38 volumio go-librespot[5775]: time="2026-01-25T22:51:38+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:38 volumio go-librespot[5775]: time="2026-01-25T22:51:38+07:00" level=debug msg="completed challenge" Jan 25 22:51:38 volumio go-librespot[5775]: time="2026-01-25T22:51:38+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 25 22:51:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:39 volumio volumio-remote-updater[628]: [2026-01-25 22:51:39] [connect] Successful connection Jan 25 22:51:39 volumio volumio[5757]: info: MYVOLUMIO Environment detected Jan 25 22:51:39 volumio volumio[5757]: info: Plugin folders cleanup Jan 25 22:51:39 volumio volumio[5757]: info: Scanning into folder /volumio/app/plugins/ Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category audio_interface Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category miscellanea Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category music_service Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category plugins.json Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category system_controller Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category user_interface Jan 25 22:51:39 volumio volumio[5757]: info: Scanning into folder /data/plugins/ Jan 25 22:51:39 volumio volumio[5757]: info: Scanning category music_service Jan 25 22:51:39 volumio volumio[5757]: info: Plugin folders cleanup completed Jan 25 22:51:39 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:51:39 volumio volumio[5757]: info: ----- Core plugins startup ---- Jan 25 22:51:39 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:51:39 volumio volumio[5757]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 22:51:39 volumio volumio[5757]: info: Adding plugin upnp to MyMusic Plugins Jan 25 22:51:39 volumio volumio[5757]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 22:51:39 volumio volumio[5757]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 22:51:39 volumio volumio[5757]: info: Loading plugins from folder /data/plugins/ Jan 25 22:51:39 volumio volumio[5757]: info: Loading plugin "system"... Jan 25 22:51:39 volumio volumio[5757]: info: Loading plugin "appearance"... Jan 25 22:51:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "network"... Jan 25 22:51:41 volumio volumio[5757]: info: Refreshing Cached IP Addresses Jan 25 22:51:41 volumio sudo[5795]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:51:41 volumio sudo[5795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:41 volumio sudo[5795]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:41 volumio sudo[5797]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "services"... Jan 25 22:51:41 volumio sudo[5797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "alsa_controller"... Jan 25 22:51:41 volumio sudo[5797]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:41 volumio sudo[5805]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 22:51:41 volumio sudo[5805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:41 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "wizard"... Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "networkfs"... Jan 25 22:51:41 volumio volumio[5757]: info: Starting Udev Watcher for removable devices Jan 25 22:51:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Jan 25 22:51:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:41 volumio volumio[5757]: info: Ignoring mount for partition: boot Jan 25 22:51:41 volumio volumio[5757]: info: Ignoring mount for partition: volumio Jan 25 22:51:41 volumio volumio[5757]: info: Ignoring mount for partition: volumio_data Jan 25 22:51:41 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "volumio_command_line_client"... Jan 25 22:51:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:41 volumio go-librespot[5828]: go-librespot daemon starting... Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "upnp"... Jan 25 22:51:41 volumio volumio[5757]: info: [1769356301834] Starting Upmpd Daemon Jan 25 22:51:41 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "my_music"... Jan 25 22:51:41 volumio volumio[5757]: info: Loading plugin "mpd"... Jan 25 22:51:41 volumio go-librespot[5829]: time="2026-01-25T22:51:41+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:41 volumio go-librespot[5829]: time="2026-01-25T22:51:41+07:00" level=debug msg="app state loaded" Jan 25 22:51:41 volumio go-librespot[5829]: time="2026-01-25T22:51:41+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+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 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+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 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=info msg="zeroconf server listening on port 37511" Jan 25 22:51:42 volumio volumio[5757]: info: Loading plugin "upnp_browser"... Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=debug msg="obtained new client token: AADjIyVxVKb33+eN+t5OSAm9qKhduGPDx1TBqbHgoaP/Qvp9VNCRsJSJDan84J+Pq5PtjcN1gqFgMUWvfnspITU/ronwUCcAdE44/HUxRwdQoQnMYrFBFn6l6qft0no0Qz/mLq3i0PYtXxfO9ZH+zwiixebGldrwY2uedHvw1zS1zsvsLEwXloZW9NgO8mvL5+GUiTXQzJ0mMY7E7pR3AiJpw2+lqo7jwPydvP7S+Vqrjqccpzy0+zbixEo=" Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=debug msg="completed challenge" Jan 25 22:51:42 volumio go-librespot[5829]: time="2026-01-25T22:51:42+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:44 volumio sudo[5805]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:45 volumio volumio[5757]: info: Starting UPNP Browser Jan 25 22:51:45 volumio volumio[5757]: info: Loading plugin "alarm-clock"... Jan 25 22:51:45 volumio volumio[5757]: info: Loading plugin "airplay_emulation"... Jan 25 22:51:45 volumio volumio[5757]: info: Starting Shairport Sync Jan 25 22:51:45 volumio volumio[5757]: info: Loading plugin "last_100"... Jan 25 22:51:45 volumio volumio[5757]: info: Loading plugin "webradio"... Jan 25 22:51:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Jan 25 22:51:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:46 volumio volumio[5757]: info: Loading plugin "i2s_dacs"... Jan 25 22:51:46 volumio volumio[5757]: info: Loading plugin "volumiodiscovery"... Jan 25 22:51:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:46 volumio go-librespot[5837]: go-librespot daemon starting... Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** For more information see Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:46 volumio volumio[5757]: *** WARNING *** For more information see Jan 25 22:51:46 volumio node[5757]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:46 volumio node[5757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:46 volumio node[5757]: *** WARNING *** For more information see Jan 25 22:51:46 volumio node[5757]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:51:46 volumio node[5757]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:51:46 volumio node[5757]: *** WARNING *** For more information see Jan 25 22:51:46 volumio volumio[5757]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 22:51:46 volumio volumio[5757]: info: Discovery: Started advertising with name: Volumio Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=debug msg="app state loaded" Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:46 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:51:46 volumio volumio[5757]: info: Loading plugin "spop"... Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=info msg="zeroconf server listening on port 39149" Jan 25 22:51:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:46 volumio go-librespot[5838]: time="2026-01-25T22:51:46+07:00" level=debug msg="obtained new client token: AAB9MPZqIxbCeEpDUUV7VJuvRzcjAbYIT2csnyTIvyc0nOijrpRE0b5zMAtDu96HTC/0+rff6sboUK8A+e/W6zJYnmXWSoadfSkzx9OqJfbSO5SppROYs7V5LIsUtMftWhSQ2z+87X9eMWRcE2LFCP83+QXJmTVTVo5SfYQ9hfasV1RUxYM+dq8Cut0jwnIVFWCqU5l9OxgH+dJvclLI8qMqzF8weOTrcFDRoXDv2KiE4mLP1qvaTMw1YNY=" Jan 25 22:51:47 volumio go-librespot[5838]: time="2026-01-25T22:51:47+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:47 volumio go-librespot[5838]: time="2026-01-25T22:51:47+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:47 volumio go-librespot[5838]: time="2026-01-25T22:51:47+07:00" level=debug msg="completed challenge" Jan 25 22:51:47 volumio go-librespot[5838]: time="2026-01-25T22:51:47+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:48 volumio volumio[5757]: info: Loading plugin "ytcr"... Jan 25 22:51:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Jan 25 22:51:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:50 volumio go-librespot[5847]: go-librespot daemon starting... Jan 25 22:51:50 volumio go-librespot[5848]: time="2026-01-25T22:51:50+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:50 volumio go-librespot[5848]: time="2026-01-25T22:51:50+07:00" level=debug msg="app state loaded" Jan 25 22:51:50 volumio go-librespot[5848]: time="2026-01-25T22:51:50+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:50 volumio volumio[5757]: info: Loading plugin "ytmusic"... Jan 25 22:51:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+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 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+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 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=info msg="zeroconf server listening on port 37799" Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=debug msg="obtained new client token: AAAzGnonXTEM5EYLBan0iuiohet9iE4wrnTubKcfzD027LiZcVK1LAkHZfncpFy5CZKzMoe4c9YXExPQLdl8f+WMVimYt29rV060AxaJzCS0GBjBFqhiXQ3jr87BpQjvtLyuSVD1NvGf64tfwPXsnbD0zjy1QXrFCJ6AqdWNrnM5MkVO/YQ4K0pU8MEuCSsz+rc7sRYCnsS9f3Btkgw8YWCvleAm9g8aEr3hFkoaJLBuzvpcSc1S0I9CakY=" Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=debug msg="completed keyexchange" Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=debug msg="completed challenge" Jan 25 22:51:51 volumio volumio-remote-updater[628]: [2026-01-25 22:51:51] [connect] Successful connection Jan 25 22:51:51 volumio go-librespot[5848]: time="2026-01-25T22:51:51+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:51:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:51 volumio volumio[5757]: info: Loading plugin "outputs"... Jan 25 22:51:51 volumio volumio[5757]: info: Loading plugin "albumart"... Jan 25 22:51:51 volumio volumio[5757]: info: Plugin example_plugin is not enabled Jan 25 22:51:51 volumio volumio[5757]: info: Loading plugin "inputs"... Jan 25 22:51:51 volumio volumio[5757]: info: Loading plugin "updater_comm"... Jan 25 22:51:52 volumio volumio[5757]: info: Plugin mpdemulation is not enabled Jan 25 22:51:52 volumio volumio[5757]: info: Loading plugin "rest_api"... Jan 25 22:51:52 volumio volumio[5757]: info: Loading plugin "websocket"... Jan 25 22:51:52 volumio volumio[5757]: info: Starting Socket.io Server version 1.7.4 Jan 25 22:51:52 volumio volumio[5757]: info: Loading plugin "RoonBridge"... Jan 25 22:51:52 volumio volumio[5757]: info: Applying required configuration parameters for plugin RoonBridge Jan 25 22:51:52 volumio volumio[5757]: info: Loading i18n strings for locale en Jan 25 22:51:52 volumio volumio[5757]: Updating browse sources language Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::initPlayerControls Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:52 volumio volumio[5757]: Express server listening on port 3000 Jan 25 22:51:52 volumio volumio[5757]: [Metrics] WebUI: 16s 11.51ms Jan 25 22:51:52 volumio volumio[5757]: info: CoreStateMachine::resetVolumioState Jan 25 22:51:52 volumio volumio[5757]: info: CoreStateMachine::getcurrentVolume Jan 25 22:51:52 volumio volumio[5757]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:51:52 volumio volumio[5869]: Forking 3 albumart workers Jan 25 22:51:53 volumio sudo[5885]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:51:53 volumio sudo[5885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:53 volumio sudo[5885]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:53 volumio sudo[5888]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:51:53 volumio sudo[5888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:53 volumio sudo[5888]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:53 volumio volumio[5757]: info: Volumio Network Manager: Network status updated: 1 Jan 25 22:51:53 volumio volumio[5757]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::pushState Jan 25 22:51:53 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::updateTrackBlock Jan 25 22:51:53 volumio volumio[5757]: info: CorePlayQueue::getTrackBlock Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:51:53 volumio volumio-remote-updater[628]: [2026-01-25 22:51:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769356311 101 Jan 25 22:51:53 volumio volumio[5757]: 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 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:53 volumio volumio[5757]: info: Reloading queue from file Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::setRepeat null single undefined Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::pushState Jan 25 22:51:53 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::setRandom null Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::pushState Jan 25 22:51:53 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:53 volumio volumio[5757]: info: Setting Device type: Raspberry PI Jan 25 22:51:53 volumio volumio[5757]: info: Completed loading Core Plugins Jan 25 22:51:53 volumio volumio[5757]: info: Preparing to generate the ALSA configuration file Jan 25 22:51:53 volumio volumio[5757]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:51:53 volumio volumio[5757]: info: CoreStateMachine::pushState Jan 25 22:51:53 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:53 volumio volumio[5757]: info: CoreCommandRouter::volumioPushState Jan 25 22:51:53 volumio volumio[5757]: info: Asound.conf file unchanged, so no further update is needed Jan 25 22:51:53 volumio volumio[5757]: info: Output device has changed, restarting MPD Jan 25 22:51:54 volumio volumio[5757]: info: Output device has changed, restarting Shairport Sync Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:54 volumio sudo[5930]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 22:51:54 volumio sudo[5930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:54 volumio volumio[5757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:54 volumio volumio[5757]: info: ___________ START PLUGINS ___________ Jan 25 22:51:54 volumio sudo[5932]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:51:54 volumio sudo[5932]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:54 volumio sudo[5932]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:54 volumio sudo[5934]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:51:54 volumio sudo[5934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:54 volumio volumio[5757]: info: ControllerMpd::onStart: Initializing MPD Jan 25 22:51:54 volumio volumio[5757]: info: Creating MPD Configuration file Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:54 volumio volumio[5757]: info: [1769356314172] CoreMusicLibrary::Adding element Media Servers Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:54 volumio sudo[5930]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:54 volumio sudo[5943]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:51:54 volumio volumio[5757]: info: UPNP Browser: Client initialized successfully Jan 25 22:51:54 volumio sudo[5943]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:54 volumio sudo[5943]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:54 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:54 volumio sudo[5945]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:51:54 volumio sudo[5945]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:54 volumio volumio[5757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:54 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 25 22:51:54 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 22:51:54 volumio systemd[1]: mpd.service: Consumed 7.422s CPU time. Jan 25 22:51:54 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 25 22:51:54 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 22:51:54 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 22:51:54 volumio volumio[5757]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:54 volumio volumio[5757]: info: [1769356314492] CoreMusicLibrary::Adding element Last_100 Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:54 volumio volumio[5757]: info: [1769356314513] CoreMusicLibrary::Adding element Webradio Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:54 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 22:51:54 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:54 volumio volumio[5757]: info: Initializing BBC Radios Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Jan 25 22:51:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:54 volumio go-librespot[5971]: go-librespot daemon starting... Jan 25 22:51:54 volumio volumio[5757]: info: Creating Spotify config file Jan 25 22:51:54 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:54 volumio go-librespot[5972]: time="2026-01-25T22:51:54+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:55 volumio sudo[5957]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 22:51:55 volumio sudo[5957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 22:51:55 volumio sudo[5957]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:55 volumio go-librespot[5972]: time="2026-01-25T22:51:55+07:00" level=info msg="zeroconf server listening on port 42193" Jan 25 22:51:56 volumio volumio[5887]: Starting albumart workers Jan 25 22:51:56 volumio volumio[5884]: Starting albumart workers Jan 25 22:51:56 volumio volumio[5757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:51:56 volumio volumio[5757]: info: [1769356316517] CoreMusicLibrary::Adding element YouTube Music Jan 25 22:51:56 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:51:56 volumio volumio[5757]: Cannot find translation for source YouTube Music Jan 25 22:51:56 volumio volumio[5889]: Starting albumart workers Jan 25 22:51:56 volumio volumio[5757]: info: Volumio Calling Home Jan 25 22:51:56 volumio sudo[5982]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 25 22:51:56 volumio sudo[5982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:56 volumio sudo[5982]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:57 volumio volumio[5757]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:51:57 volumio volumio[5757]: info: Discovery: Found device Volumio Jan 25 22:51:57 volumio volumio[5757]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:57 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:57 volumio volumio[5757]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:51:57 volumio volumio[5757]: info: Discovery: Found device Volumio Jan 25 22:51:57 volumio volumio[5757]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:57 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:57 volumio volumio[5757]: info: MPD Permissions set Jan 25 22:51:57 volumio volumio[5757]: info: MPD Permissions set Jan 25 22:51:57 volumio volumio[5757]: info: Upmpdcli Daemon Started Jan 25 22:51:57 volumio volumio[5757]: info: Spotify config file written Jan 25 22:51:58 volumio sudo[5989]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 22:51:58 volumio sudo[5989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:58 volumio volumio[5757]: 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 25 22:51:58 volumio volumio[5757]: info: Volumio called home Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 25 22:51:58 volumio systemd[1]: go-librespot-daemon.service: Killing process 5977 (go-librespot) with signal SIGKILL. Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:51:58 volumio go-librespot[6001]: go-librespot daemon starting... Jan 25 22:51:58 volumio sudo[5989]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:51:58 volumio volumio[5757]: info: No need to fix Spotify hosts Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=debug msg="app state loaded" Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:51:58 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:51:58 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:51:58 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:51:58 volumio go-librespot[6011]: time="2026-01-25T22:51:58+07:00" level=info msg="zeroconf server listening on port 41787" Jan 25 22:51:59 volumio volumio[5757]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:51:59 volumio volumio[5757]: SPOTIFY: BQCjgy8wzRi8TUwdN9narmuu03aeN2iqDkCJUlj0PAN2-Wrtpcg74L8qYXPfJcYJ8Os_uOcmXMNyjIRKIbzyb4tDoo3wvThNmHRh9X3BhhOtM4hQCnkliDdL5JGly2c5TgMqjA_nvKvrisCAmzSNvt_ltpIRWEON5DymuAIZVurxwdY8635UFFtH8wGSjDmvY3Ye5ObD1e_1O85RpLM9Gd0gas7Bz7Bpn5pZ5G7b7A_XF9MFPN8xVFgOQcVXjbU4WTzBQTp3EQ1I3pj-1nv-8awYzwCi77hvRaXwsY98o-BixqAAUkK2EWZ7 Jan 25 22:51:59 volumio volumio[5757]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:51:59 volumio go-librespot[6011]: time="2026-01-25T22:51:59+07:00" level=debug msg="obtained new client token: AACJjJBRX7k0ONfiD8Xue1dCzM0aOfXm7Ng3gbiYJr714UvCFvFzAOmScHxJAPdp6VutSIHkMOKAc49+Tts+gP5jCS307RU2+CU+RKP6njTq44tsJMhC8xPk6je2cERFhnkr1jJIj20t4zdZitGIF8lBQY3hGjxsMquxH0ptSm0SlATTNRVi/CZrYx+EdiimS18pmuctU4eiW9NPo6ei4WSvOO8x9X7Hu2ERwMrl9KvwX1PdegLNYI4K" Jan 25 22:51:59 volumio volumio[5757]: info: New Spotify access token = BQCjgy8wzRi8TUwdN9narmuu03aeN2iqDkCJUlj0PAN2-Wrtpcg74L8qYXPfJcYJ8Os_uOcmXMNyjIRKIbzyb4tDoo3wvThNmHRh9X3BhhOtM4hQCnkliDdL5JGly2c5TgMqjA_nvKvrisCAmzSNvt_ltpIRWEON5DymuAIZVurxwdY8635UFFtH8wGSjDmvY3Ye5ObD1e_1O85RpLM9Gd0gas7Bz7Bpn5pZ5G7b7A_XF9MFPN8xVFgOQcVXjbU4WTzBQTp3EQ1I3pj-1nv-8awYzwCi77hvRaXwsY98o-BixqAAUkK2EWZ7 Jan 25 22:51:59 volumio volumio[5757]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 25 22:51:59 volumio volumio[5757]: info: Starting Shairport Sync Jan 25 22:51:59 volumio go-librespot[6011]: time="2026-01-25T22:51:59+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:51:59 volumio volumio[5757]: info: Starting Shairport Sync Jan 25 22:51:59 volumio volumio[5757]: info: Starting Shairport Sync Jan 25 22:51:59 volumio go-librespot[6011]: time="2026-01-25T22:51:59+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 25 22:51:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:51:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:51:59 volumio sudo[6028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:59 volumio sudo[6028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:59 volumio sudo[6030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:59 volumio sudo[6030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:59 volumio sudo[6032]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:51:59 volumio sudo[6032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:51:59 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 22:51:59 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 22:51:59 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:51:59 volumio systemd[1]: shairport-sync.service: Consumed 2.282s CPU time. Jan 25 22:51:59 volumio volumio[5757]: info: CoreCommandRouter::volumioGetState Jan 25 22:51:59 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:51:59 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:51:59 volumio sudo[6028]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:59 volumio sudo[6032]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:59 volumio sudo[6030]: pam_unix(sudo:session): session closed for user root Jan 25 22:51:59 volumio volumio[5757]: info: Shairport-Sync Started Jan 25 22:51:59 volumio volumio[5757]: Error adding Membership: Error: addMembership EINVAL Jan 25 22:51:59 volumio volumio[5757]: info: Shairport-Sync Started Jan 25 22:51:59 volumio volumio[5757]: info: Shairport-Sync Started Jan 25 22:52:00 volumio volumio[5757]: 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 25 22:52:00 volumio volumio[5757]: info: Spotify Successfully logged in Jan 25 22:52:00 volumio volumio[5757]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:00 volumio volumio[5757]: info: [1769356320173] CoreMusicLibrary::Adding element Spotify Jan 25 22:52:00 volumio volumio[5757]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:00 volumio volumio[5757]: Cannot find translation for source YouTube Music Jan 25 22:52:00 volumio volumio[5757]: Cannot find translation for source Spotify Jan 25 22:52:00 volumio volumio[5757]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 25 22:52:00 volumio volumio[5757]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:52:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:00 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:01 volumio volumio[5757]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:52:01 volumio volumio[5757]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:01 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:01 volumio volumio[5757]: info: CoreStateMachine::pushState Jan 25 22:52:01 volumio volumio[5757]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:01 volumio volumio[5757]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:02 volumio volumio[5757]: info: go-librespot daemon successfully initialized Jan 25 22:52:02 volumio mpd[5979]: 2026-01-25T22:52:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 22:52:02 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 22:52:02 volumio sudo[5934]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:02 volumio sudo[5945]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:02 volumio volumio[5757]: error: MPD error: The expression evaluated to a falsy value: Jan 25 22:52:02 volumio volumio[5757]: assert.ok(self.idling) Jan 25 22:52:02 volumio volumio[5757]: error: The expression evaluated to a falsy value: Jan 25 22:52:02 volumio volumio[5757]: assert.ok(self.idling) Jan 25 22:52:02 volumio volumio[5757]: error: updateQueue error: null Jan 25 22:52:02 volumio volumio[5757]: info: MPD running with PID5979 Jan 25 22:52:02 volumio volumio[5757]: ,establishing connection Jan 25 22:52:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 25 22:52:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:02 volumio volumio[5757]: info: Completed starting Core Plugins Jan 25 22:52:02 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:52:02 volumio volumio[5757]: info: ----- MyVolumio plugins startup ---- Jan 25 22:52:02 volumio volumio[5757]: info: ------------------------------------------- Jan 25 22:52:02 volumio volumio[5757]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 22:52:02 volumio volumio[5757]: error: updateQueue error: null Jan 25 22:52:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:02 volumio go-librespot[6071]: go-librespot daemon starting... Jan 25 22:52:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:02 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:02 volumio go-librespot[6072]: time="2026-01-25T22:52:02+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:02 volumio go-librespot[6072]: time="2026-01-25T22:52:02+07:00" level=debug msg="app state loaded" Jan 25 22:52:02 volumio go-librespot[6072]: time="2026-01-25T22:52:02+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+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 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+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 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+07:00" level=info msg="zeroconf server listening on port 41409" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+07:00" level=debug msg="obtained new client token: AAAVGZs0BTaTIuCf6Zh+akufX7Ibb0ImVXZZpsXWvKGM+g7WkNERCnxYoyh71ZfDOEzTqp5aD5uRsl+oxt8FzOye46tWi8u0Rr1kZ2+TwiNsQy96er6pri6ZO/LG2XNrplJWdFsj9HNk8ogG9WdVMPdHQVj1QZlJuT1XcbwhnR0v4weN5sobqeBL69u2cGKuPWWnS0zad/HPtnjthwf3th8MoS31QxqGV8lblvKaV71KTjS+FZQrZ7Jezdk=" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:03 volumio go-librespot[6072]: time="2026-01-25T22:52:03+07:00" level=debug msg="completed challenge" Jan 25 22:52:04 volumio go-librespot[6072]: time="2026-01-25T22:52:04+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:04 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:05 volumio volumio[5757]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:05 volumio volumio[5757]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:52:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:06 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 25 22:52:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:07 volumio go-librespot[6081]: go-librespot daemon starting... Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=debug msg="app state loaded" Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:07 volumio volumio[5757]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:52:07 volumio go-librespot[6082]: time="2026-01-25T22:52:07+07:00" level=info msg="zeroconf server listening on port 36871" Jan 25 22:52:08 volumio go-librespot[6082]: time="2026-01-25T22:52:08+07:00" level=debug msg="obtained new client token: AADgyfm4uA84z9OLOqhCjVcvVN+ieAZM9w+vryGqyXSvWzMA3gFSOQuJibiwv8s6eqJW0pVhNSTbO5qPVx/CoqYYbbmAvDXFPgrxSRCBxdqPk7xhaamQXaB6MQBefZvOTziO3Wi5XkyDIXDzgAT9NIvQ+yFySWj94EsoYhHWfWohtCy9mBdNFBurgZH+/qZNeXFu8ZXm2mRvP1Uni83F08ADA5cr1OC/CR0UxCLGkpHxXa5xGppmlUFi" Jan 25 22:52:08 volumio go-librespot[6082]: time="2026-01-25T22:52:08+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:08 volumio volumio[5757]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:08 volumio go-librespot[6082]: time="2026-01-25T22:52:08+07:00" level=debug msg="new websocket client" Jan 25 22:52:08 volumio volumio[5757]: info: Connection to go-librespot Websocket established Jan 25 22:52:08 volumio go-librespot[6082]: time="2026-01-25T22:52: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 25 22:52:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:08 volumio volumio[5757]: info: Connection to go-librespot Websocket closed Jan 25 22:52:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:08 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:10 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:11 volumio volumio[5757]: info: Getting Spotify volume Jan 25 22:52:11 volumio volumio[5757]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:52:11 volumio volumio[5757]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:52:11 volumio volumio[5757]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 25 22:52:11 volumio volumio[5757]: errno: -111, Jan 25 22:52:11 volumio volumio[5757]: code: 'ECONNREFUSED', Jan 25 22:52:11 volumio volumio[5757]: syscall: 'connect', Jan 25 22:52:11 volumio volumio[5757]: address: '127.0.0.1', Jan 25 22:52:11 volumio volumio[5757]: port: 9879, Jan 25 22:52:11 volumio volumio[5757]: response: undefined Jan 25 22:52:11 volumio volumio[5757]: } Jan 25 22:52:11 volumio volumio[5757]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:52:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 25 22:52:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:11 volumio go-librespot[6102]: go-librespot daemon starting... Jan 25 22:52:11 volumio go-librespot[6103]: time="2026-01-25T22:52:11+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:11 volumio go-librespot[6103]: time="2026-01-25T22:52:11+07:00" level=debug msg="app state loaded" Jan 25 22:52:11 volumio go-librespot[6103]: time="2026-01-25T22:52:11+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+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 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+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 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+07:00" level=info msg="zeroconf server listening on port 39591" Jan 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+07:00" level=debug msg="obtained new client token: AAAXxKfORioj3z9JbZY+z3cRDPs01waQTXsmvgoJ9Q/D+9fcQqt5/IGqcg/K1JxUtFBL3VOq/psccHdcIlmfsANvIFJQnld9jEX7mfbnygP0q1Ij79HXgSu5LagD+IwdUAYk1A1ctaxSpS6S/hYwWKjZ1gK6nelf5p5zm6hhvrbxPefiTf1iPtmxWbQR4QgHEGxYh69H1HlVtQD7u3Q+P+sXoquxYDguKsA3NLvZZ9lxKdNjHIV21cjHbmM=" Jan 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:12 volumio go-librespot[6103]: time="2026-01-25T22:52:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 25 22:52:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:12 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:12 volumio sudo[6127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 22:51' Jan 25 22:52:12 volumio sudo[6127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:13 volumio sudo[6127]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:13 volumio volumio-remote-updater[628]: [2026-01-25 22:52:13] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 25 22:52:13 volumio volumio-remote-updater[628]: [2026-01-25 22:52:13] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 25 22:52:13 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:13 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 25 22:52:13 volumio systemd[1]: volumio.service: Consumed 56.211s CPU time. Jan 25 22:52:13 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 22:52:13 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 22:52:13 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6113. Jan 25 22:52:13 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 25 22:52:13 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 25 22:52:13 volumio systemd[1]: volumio.service: Consumed 56.211s CPU time. Jan 25 22:52:13 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 25 22:52:13 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 25 22:52:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:14 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 25 22:52:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:15 volumio go-librespot[6155]: go-librespot daemon starting... Jan 25 22:52:15 volumio go-librespot[6156]: time="2026-01-25T22:52:15+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:15 volumio go-librespot[6156]: time="2026-01-25T22:52:15+07:00" level=debug msg="app state loaded" Jan 25 22:52:15 volumio go-librespot[6156]: time="2026-01-25T22:52:15+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52: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-gew1.spotify.com:80]" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+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 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+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 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+07:00" level=info msg="zeroconf server listening on port 42483" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+07:00" level=debug msg="obtained new client token: AABBk8xxqj7HpVri1YizRvhs07GhN1yADHVYx9BFd3c5akg0RSTCuGBDL+mxbfgSQpoSCXZxXcaEbiEa1URJgqk4IihNlH2pJQyUvdFEP7/0HrtR08OQW+VpHOp8xqH9ITCCc4Nv+KJ/raXRe+FcSg7MyW0ODUIe1zkgAK4vvC4jDqlpPOifkuRDR55LqdGPwTJrQin1JRE0fEn7roVibo81epr8pHa3rzEnihv6dwq0bZO8jBG6KMOSWLc=" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:16 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52:16+07:00" level=debug msg="completed challenge" Jan 25 22:52:16 volumio go-librespot[6156]: time="2026-01-25T22:52: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 25 22:52:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:17 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:17 volumio volumio[6140]: info: ----- Volumio3 ---- Jan 25 22:52:17 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:17 volumio volumio[6140]: info: ----- System startup ---- Jan 25 22:52:17 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:18 volumio volumio-remote-updater[628]: [2026-01-25 22:52:18] [connect] Successful connection Jan 25 22:52:18 volumio volumio[6140]: info: MYVOLUMIO Environment detected Jan 25 22:52:18 volumio volumio[6140]: info: Plugin folders cleanup Jan 25 22:52:18 volumio volumio[6140]: info: Scanning into folder /volumio/app/plugins/ Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category audio_interface Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category miscellanea Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category music_service Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category plugins.json Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category system_controller Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category user_interface Jan 25 22:52:18 volumio volumio[6140]: info: Scanning into folder /data/plugins/ Jan 25 22:52:18 volumio volumio[6140]: info: Scanning category music_service Jan 25 22:52:18 volumio volumio[6140]: info: Plugin folders cleanup completed Jan 25 22:52:18 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:18 volumio volumio[6140]: info: ----- Core plugins startup ---- Jan 25 22:52:18 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:18 volumio volumio[6140]: info: Loading plugins from folder /volumio/app/plugins/ Jan 25 22:52:18 volumio volumio[6140]: info: Adding plugin upnp to MyMusic Plugins Jan 25 22:52:18 volumio volumio[6140]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 25 22:52:18 volumio volumio[6140]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 25 22:52:18 volumio volumio[6140]: info: Loading plugins from folder /data/plugins/ Jan 25 22:52:18 volumio volumio[6140]: info: Loading plugin "system"... Jan 25 22:52:18 volumio volumio[6140]: info: Loading plugin "appearance"... Jan 25 22:52:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:18 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 25 22:52:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:20 volumio go-librespot[6175]: go-librespot daemon starting... Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+07:00" level=debug msg="app state loaded" Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:20 volumio volumio[6140]: info: Loading plugin "network"... Jan 25 22:52:20 volumio volumio[6140]: info: Refreshing Cached IP Addresses Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+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 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+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 25 22:52:20 volumio sudo[6184]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+07:00" level=info msg="zeroconf server listening on port 32989" Jan 25 22:52:20 volumio sudo[6186]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:52:20 volumio volumio[6140]: info: Loading plugin "services"... Jan 25 22:52:20 volumio sudo[6184]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:20 volumio sudo[6186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:20 volumio volumio[6140]: info: Loading plugin "alsa_controller"... Jan 25 22:52:20 volumio sudo[6186]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:20 volumio sudo[6184]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:20 volumio sudo[6193]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 25 22:52:20 volumio sudo[6193]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:20 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:20 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:52:20 volumio volumio[6140]: info: Loading plugin "wizard"... Jan 25 22:52:20 volumio volumio[6140]: info: Loading plugin "networkfs"... Jan 25 22:52:20 volumio go-librespot[6176]: time="2026-01-25T22:52:20+07:00" level=debug msg="obtained new client token: AABLduC3gful0g0iTJxnFsWJkEErsymm/3MnDJ83qe7L36hyOpTr0Es2Xt6BTJRd0vE8+wD60vGZOpv9Gx/7WQ3XXT3zETxkPwHtVBScfEyawxJXW09QuF56Plz5bPDihWpS6B/czzVB25TsCORjx6CG85uFIalieKfBIJyaoo8d9TgUxsYC9mLsh3BThyYypOBqr3G9CMZeSr6gqxe9jJyTSDYij/MlwQaTminNeCFAUQMjgPypuMXsvGM=" Jan 25 22:52:20 volumio volumio[6140]: info: Starting Udev Watcher for removable devices Jan 25 22:52:21 volumio volumio[6140]: info: Ignoring mount for partition: boot Jan 25 22:52:21 volumio volumio[6140]: info: Ignoring mount for partition: volumio Jan 25 22:52:21 volumio volumio[6140]: info: Ignoring mount for partition: volumio_data Jan 25 22:52:21 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:52:21 volumio volumio[6140]: info: Loading plugin "volumio_command_line_client"... Jan 25 22:52:21 volumio volumio[6140]: info: Loading plugin "upnp"... Jan 25 22:52:21 volumio go-librespot[6176]: time="2026-01-25T22:52:21+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:21 volumio volumio[6140]: info: [1769356341064] Starting Upmpd Daemon Jan 25 22:52:21 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:52:21 volumio volumio[6140]: info: Loading plugin "my_music"... Jan 25 22:52:21 volumio volumio[6140]: info: Loading plugin "mpd"... Jan 25 22:52:21 volumio go-librespot[6176]: time="2026-01-25T22:52:21+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:21 volumio go-librespot[6176]: time="2026-01-25T22:52:21+07:00" level=debug msg="completed challenge" Jan 25 22:52:21 volumio go-librespot[6176]: time="2026-01-25T22:52:21+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:21 volumio volumio[6140]: info: Loading plugin "upnp_browser"... Jan 25 22:52:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:22 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:23 volumio sudo[6193]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 25 22:52:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:24 volumio go-librespot[6218]: go-librespot daemon starting... Jan 25 22:52:24 volumio go-librespot[6219]: time="2026-01-25T22:52:24+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:24 volumio go-librespot[6219]: time="2026-01-25T22:52:24+07:00" level=debug msg="app state loaded" Jan 25 22:52:24 volumio go-librespot[6219]: time="2026-01-25T22:52:24+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:24 volumio volumio[6140]: info: Starting UPNP Browser Jan 25 22:52:24 volumio volumio[6140]: info: Loading plugin "alarm-clock"... Jan 25 22:52:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:24 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "airplay_emulation"... Jan 25 22:52:25 volumio volumio[6140]: info: Starting Shairport Sync Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "last_100"... Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "webradio"... Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+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 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+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 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+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 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=info msg="zeroconf server listening on port 37343" Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "i2s_dacs"... Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "volumiodiscovery"... Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** For more information see Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:52:25 volumio volumio[6140]: *** WARNING *** For more information see Jan 25 22:52:25 volumio node[6140]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 25 22:52:25 volumio node[6140]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:52:25 volumio node[6140]: *** WARNING *** For more information see Jan 25 22:52:25 volumio node[6140]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 25 22:52:25 volumio node[6140]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 25 22:52:25 volumio node[6140]: *** WARNING *** For more information see Jan 25 22:52:25 volumio volumio[6140]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 25 22:52:25 volumio volumio[6140]: info: Discovery: Started advertising with name: Volumio Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=debug msg="obtained new client token: AACY46TqWKDq2iI1WXEe4yHvI+hVtbSJhVXxus0VPcVEcV7JUl28aYnvvsYKaOD579ydVhRLjBYBstAJrKcHcyGrm9JbKp6PGlKCO5IQCA9nbQbYj5PPDtjMv5r2ZjLiT+pg37VGTXTWHZguuyouB+XFXmFCamJYCU0DKhfFuKP2JfxHMVkKblwGmR6vKSwf7MToO8pjTAoPSt6ZrQBgVlOtG9l6Ggi0BFP32vSVwiWsBt56DbSRy8LCVg8=" Jan 25 22:52:25 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 25 22:52:25 volumio volumio[6140]: info: Loading plugin "spop"... Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=debug msg="completed challenge" Jan 25 22:52:25 volumio go-librespot[6219]: time="2026-01-25T22:52:25+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:26 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:27 volumio volumio[6140]: info: Loading plugin "ytcr"... Jan 25 22:52:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 25 22:52:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:28 volumio go-librespot[6228]: go-librespot daemon starting... Jan 25 22:52:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:28 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:28 volumio go-librespot[6229]: time="2026-01-25T22:52:28+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:28 volumio go-librespot[6229]: time="2026-01-25T22:52:28+07:00" level=debug msg="app state loaded" Jan 25 22:52:28 volumio go-librespot[6229]: time="2026-01-25T22:52:28+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+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 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+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 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=info msg="zeroconf server listening on port 36241" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=debug msg="obtained new client token: AADNVtCOXyeO81y8sqUKuQHB5Jv/O+4E0qdalIjBCpxz+XzJHx2IqfntvYSPb2/SNdzHVDs0W3Kg7TXjaDea3QCYy8x6LSbfCHIqEZNYfxdSnKRAf1DM0Jg+C+rEqc6ZSaA1nM5pvcXjIkAsRtqRDsF32tNZ1IcxkihxBJkW9bO3jBgMwrSezha+IwjfKZLsAu4tbRVghhrX/qLbLOXSqibeVy/kkxt88GnuL47XesrRSNmDKr9+cuiZOIA=" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=debug msg="completed challenge" Jan 25 22:52:29 volumio go-librespot[6229]: time="2026-01-25T22:52:29+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:30 volumio volumio[6140]: info: Loading plugin "ytmusic"... Jan 25 22:52:30 volumio volumio-remote-updater[628]: [2026-01-25 22:52:30] [connect] Successful connection Jan 25 22:52:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:30 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "outputs"... Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "albumart"... Jan 25 22:52:31 volumio volumio[6140]: info: Plugin example_plugin is not enabled Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "inputs"... Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "updater_comm"... Jan 25 22:52:31 volumio volumio[6140]: info: Plugin mpdemulation is not enabled Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "rest_api"... Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "websocket"... Jan 25 22:52:31 volumio volumio[6140]: info: Starting Socket.io Server version 1.7.4 Jan 25 22:52:31 volumio volumio[6140]: info: Loading plugin "RoonBridge"... Jan 25 22:52:31 volumio volumio[6140]: info: Applying required configuration parameters for plugin RoonBridge Jan 25 22:52:31 volumio volumio[6140]: info: Loading i18n strings for locale en Jan 25 22:52:31 volumio volumio[6140]: Updating browse sources language Jan 25 22:52:31 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:32 volumio volumio[6250]: Forking 3 albumart workers Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::initPlayerControls Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:52:32 volumio volumio[6140]: Express server listening on port 3000 Jan 25 22:52:32 volumio volumio[6140]: [Metrics] WebUI: 16s 153.39ms Jan 25 22:52:32 volumio volumio[6140]: info: CoreStateMachine::resetVolumioState Jan 25 22:52:32 volumio volumio[6140]: info: CoreStateMachine::getcurrentVolume Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:52:32 volumio sudo[6296]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 25 22:52:32 volumio sudo[6296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:32 volumio sudo[6298]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 25 22:52:32 volumio sudo[6298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:32 volumio sudo[6296]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:32 volumio volumio[6140]: info: Volumio Network Manager: Network status updated: 1 Jan 25 22:52:32 volumio sudo[6298]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:32 volumio volumio[6140]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:52:32 volumio volumio[6140]: info: CoreStateMachine::pushState Jan 25 22:52:32 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:32 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:32 volumio volumio[6140]: info: CoreStateMachine::updateTrackBlock Jan 25 22:52:32 volumio volumio[6140]: info: CorePlayQueue::getTrackBlock Jan 25 22:52:32 volumio volumio[6140]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:52:32 volumio volumio-remote-updater[628]: [2026-01-25 22:52:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769356350 101 Jan 25 22:52:32 volumio volumio[6140]: 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 25 22:52:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 25 22:52:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:33 volumio go-librespot[6304]: go-librespot daemon starting... Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:33 volumio volumio[6140]: info: Reloading queue from file Jan 25 22:52:33 volumio volumio[6140]: info: CoreStateMachine::setRepeat null single undefined Jan 25 22:52:33 volumio volumio[6140]: info: CoreStateMachine::pushState Jan 25 22:52:33 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=debug msg="app state loaded" Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:33 volumio volumio[6140]: info: CoreStateMachine::setRandom null Jan 25 22:52:33 volumio volumio[6140]: info: CoreStateMachine::pushState Jan 25 22:52:33 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:33 volumio volumio[6140]: info: Setting Device type: Raspberry PI Jan 25 22:52:33 volumio volumio[6140]: info: Completed loading Core Plugins Jan 25 22:52:33 volumio volumio[6140]: info: Preparing to generate the ALSA configuration file Jan 25 22:52:33 volumio volumio[6140]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:52:33 volumio volumio[6140]: info: CoreStateMachine::pushState Jan 25 22:52:33 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:33 volumio volumio[6140]: info: Asound.conf file unchanged, so no further update is needed Jan 25 22:52:33 volumio volumio[6140]: info: Output device has changed, restarting MPD Jan 25 22:52:33 volumio volumio[6140]: info: Output device has changed, restarting Shairport Sync Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:33 volumio sudo[6319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 25 22:52:33 volumio sudo[6319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:33 volumio volumio[6140]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:52:33 volumio volumio[6140]: info: ___________ START PLUGINS ___________ Jan 25 22:52:33 volumio sudo[6322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:52:33 volumio sudo[6322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:33 volumio volumio[6140]: info: ControllerMpd::onStart: Initializing MPD Jan 25 22:52:33 volumio volumio[6140]: info: Creating MPD Configuration file Jan 25 22:52:33 volumio sudo[6322]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:33 volumio sudo[6324]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:33 volumio volumio[6140]: info: [1769356353730] CoreMusicLibrary::Adding element Media Servers Jan 25 22:52:33 volumio sudo[6324]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:33 volumio sudo[6319]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:33 volumio sudo[6333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 25 22:52:33 volumio sudo[6333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:33 volumio volumio[6140]: info: UPNP Browser: Client initialized successfully Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:52:33 volumio sudo[6333]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:33 volumio go-librespot[6309]: time="2026-01-25T22:52:33+07:00" level=info msg="zeroconf server listening on port 35271" Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:33 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 25 22:52:33 volumio sudo[6334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 25 22:52:33 volumio sudo[6334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:33 volumio volumio[6140]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:33 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:34 volumio volumio[6140]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:34 volumio volumio[6140]: info: [1769356354008] CoreMusicLibrary::Adding element Last_100 Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:34 volumio volumio[6140]: info: [1769356354026] CoreMusicLibrary::Adding element Webradio Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:34 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 25 22:52:34 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 22:52:34 volumio systemd[1]: mpd.service: Consumed 7.503s CPU time. Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:52:34 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 25 22:52:34 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 22:52:34 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 22:52:34 volumio volumio[6140]: info: Initializing BBC Radios Jan 25 22:52:34 volumio go-librespot[6309]: time="2026-01-25T22:52:34+07:00" level=debug msg="obtained new client token: AAAIsHvHzvMgShIX9IJVP2AjDzYOL3FWLOpwuMlaqQgoO+zz8YuA0di8fb/oQBcBHc2N4ha/Fjw8hoGoQ6qwUHGZU2w/T7dzZqnzEQqjKGcJy5SIoSx9dSkqZpLVVHMrVpRF+kOa8+hNEMr6AJhl3EeT+xU6WrvvgxRoYqP/Cpw1q3bwAxFEKMGkOmS7SxVFnw+WeRF72ocAow0pBG2eI/fcESV6nRo1p78axHeLgP7NIkJ/MiAWQaSb" Jan 25 22:52:34 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 22:52:34 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 22:52:34 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 25 22:52:34 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 25 22:52:34 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 25 22:52:34 volumio go-librespot[6309]: time="2026-01-25T22:52:34+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:34 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 25 22:52:34 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 25 22:52:34 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 25 22:52:34 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 25 22:52:34 volumio go-librespot[6309]: time="2026-01-25T22:52:34+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:34 volumio go-librespot[6309]: time="2026-01-25T22:52:34+07:00" level=debug msg="completed challenge" Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:34 volumio volumio[6140]: info: Creating Spotify config file Jan 25 22:52:34 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:34 volumio go-librespot[6309]: time="2026-01-25T22:52:34+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 25 22:52:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:34 volumio sudo[6359]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 25 22:52:34 volumio sudo[6359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 25 22:52:34 volumio sudo[6359]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:34 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:35 volumio volumio[6260]: Starting albumart workers Jan 25 22:52:35 volumio volumio[6140]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:35 volumio volumio[6140]: info: [1769356355566] CoreMusicLibrary::Adding element YouTube Music Jan 25 22:52:35 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:35 volumio volumio[6140]: Cannot find translation for source YouTube Music Jan 25 22:52:35 volumio volumio[6140]: info: Volumio Calling Home Jan 25 22:52:35 volumio sudo[6366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 25 22:52:35 volumio sudo[6366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:35 volumio volumio[6261]: Starting albumart workers Jan 25 22:52:35 volumio sudo[6366]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:35 volumio volumio[6262]: Starting albumart workers Jan 25 22:52:36 volumio volumio[6140]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:52:36 volumio volumio[6140]: info: Discovery: Found device Volumio Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:36 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:36 volumio volumio[6140]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 25 22:52:36 volumio volumio[6140]: info: Discovery: Found device Volumio Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:36 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:36 volumio volumio[6140]: info: MPD Permissions set Jan 25 22:52:36 volumio volumio[6140]: info: MPD Permissions set Jan 25 22:52:36 volumio volumio[6140]: info: Upmpdcli Daemon Started Jan 25 22:52:36 volumio volumio[6140]: info: Volumio called home Jan 25 22:52:36 volumio volumio[6140]: info: Spotify config file written Jan 25 22:52:36 volumio sudo[6373]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 25 22:52:36 volumio volumio[6140]: 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 25 22:52:36 volumio sudo[6373]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:36 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:36 volumio go-librespot[6380]: go-librespot daemon starting... Jan 25 22:52:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:37 volumio sudo[6373]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:37 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:37 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 25 22:52:37 volumio volumio[6140]: info: No need to fix Spotify hosts Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=debug msg="app state loaded" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 25 22:52:37 volumio go-librespot[6383]: time="2026-01-25T22:52:37+07:00" level=info msg="zeroconf server listening on port 36249" Jan 25 22:52:38 volumio go-librespot[6383]: time="2026-01-25T22:52:38+07:00" level=debug msg="obtained new client token: AABFh9MSh6SQpQqPVOPx5c0ZFxPEokEgdxx4Kr1xQv86eN89zG5XPN0urXT/EGPhn5l7opeEvc28cf1tHZnt8r0Oj3ocmy77w4IFEkze0lDksqOfpW+9d4NUgaV+sNBaZ+J9luHsZjCTEFansJ5nYdUTs5DRazURfgwcsYM505cVoTF1al7XFQAhYDCzpllmdPX5SPxUMOS/x3ydpXXbcP5ZfJGmm9lMrCnkMV7dWMRTlHyDsTSv9p9f" Jan 25 22:52:38 volumio go-librespot[6383]: time="2026-01-25T22:52:38+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:38 volumio go-librespot[6383]: time="2026-01-25T22:52:38+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:38 volumio go-librespot[6383]: time="2026-01-25T22:52:38+07:00" level=debug msg="completed challenge" Jan 25 22:52:38 volumio volumio[6140]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:52:38 volumio volumio[6140]: SPOTIFY: BQD85LNChNNSYYxBcV-qorYe0fL3-RRmcV5IkeBNwlSYoIjReRtxVa9b7kRbnUBk8nVtnu_QKrprjY0mK8Wx21emY-vGduNTG9WRLEHFzFuvuTnSTnopPxCDxBsT3jjMDh5OCa1RlA_MBEzTIIY48eQedey3C4rl5v6qBj_duK6O6rmytb0ooRBgGCAGIcBvv_V4mJHf5gqB5yT3-iG169gnfvyTzDJnQ7EZ0QLbruEl6emgPawUSjArNFlqsakhJ9Yl5SzXpia5i_YUa8D2LlVA9Q0M7X60MoGV4QRm7JgNw_BjuVS-Dis_ Jan 25 22:52:38 volumio volumio[6140]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 25 22:52:38 volumio volumio[6140]: info: New Spotify access token = BQD85LNChNNSYYxBcV-qorYe0fL3-RRmcV5IkeBNwlSYoIjReRtxVa9b7kRbnUBk8nVtnu_QKrprjY0mK8Wx21emY-vGduNTG9WRLEHFzFuvuTnSTnopPxCDxBsT3jjMDh5OCa1RlA_MBEzTIIY48eQedey3C4rl5v6qBj_duK6O6rmytb0ooRBgGCAGIcBvv_V4mJHf5gqB5yT3-iG169gnfvyTzDJnQ7EZ0QLbruEl6emgPawUSjArNFlqsakhJ9Yl5SzXpia5i_YUa8D2LlVA9Q0M7X60MoGV4QRm7JgNw_BjuVS-Dis_ Jan 25 22:52:38 volumio volumio[6140]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 25 22:52:38 volumio go-librespot[6383]: time="2026-01-25T22:52:38+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 25 22:52:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:38 volumio volumio[6140]: info: Starting Shairport Sync Jan 25 22:52:38 volumio volumio[6140]: info: Starting Shairport Sync Jan 25 22:52:38 volumio volumio[6140]: info: Starting Shairport Sync Jan 25 22:52:38 volumio sudo[6415]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:52:38 volumio sudo[6415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:38 volumio sudo[6417]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:52:38 volumio sudo[6417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:38 volumio sudo[6420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 25 22:52:38 volumio sudo[6420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:38 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 22:52:38 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 22:52:38 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:52:38 volumio systemd[1]: shairport-sync.service: Consumed 2.267s CPU time. Jan 25 22:52:38 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:52:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:38 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:38 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:38 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:38 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 25 22:52:38 volumio sudo[6415]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:38 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 25 22:52:38 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:52:39 volumio volumio[6140]: info: Shairport-Sync Started Jan 25 22:52:39 volumio volumio[6140]: Error adding Membership: Error: addMembership EINVAL Jan 25 22:52:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 25 22:52:39 volumio sudo[6417]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:39 volumio sudo[6420]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:39 volumio volumio[6140]: info: Shairport-Sync Started Jan 25 22:52:39 volumio volumio[6140]: info: Shairport-Sync Started Jan 25 22:52:39 volumio volumio[6140]: 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 25 22:52:39 volumio volumio[6140]: info: Spotify Successfully logged in Jan 25 22:52:39 volumio volumio[6140]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 25 22:52:39 volumio volumio[6140]: info: [1769356359264] CoreMusicLibrary::Adding element Spotify Jan 25 22:52:39 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 25 22:52:39 volumio volumio[6140]: Cannot find translation for source YouTube Music Jan 25 22:52:39 volumio volumio[6140]: Cannot find translation for source Spotify Jan 25 22:52:39 volumio volumio[6140]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 25 22:52:39 volumio volumio[6140]: info: CoreCommandRouter::volumioRetrievevolume Jan 25 22:52:40 volumio volumio[6140]: info: VolumeController:: Volume=100 Mute =false Jan 25 22:52:40 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:40 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:40 volumio volumio[6140]: info: CoreStateMachine::pushState Jan 25 22:52:40 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:40 volumio volumio[6140]: info: CoreCommandRouter::volumioPushState Jan 25 22:52:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:40 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:41 volumio volumio[6140]: info: go-librespot daemon successfully initialized Jan 25 22:52:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 25 22:52:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:41 volumio go-librespot[6455]: go-librespot daemon starting... Jan 25 22:52:41 volumio go-librespot[6456]: time="2026-01-25T22:52:41+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:41 volumio go-librespot[6456]: time="2026-01-25T22:52:41+07:00" level=debug msg="app state loaded" Jan 25 22:52:41 volumio go-librespot[6456]: time="2026-01-25T22:52:41+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:42 volumio mpd[6364]: 2026-01-25T22:52:42 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 25 22:52:42 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 25 22:52:42 volumio sudo[6324]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:42 volumio sudo[6334]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+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 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+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 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+07:00" level=info msg="zeroconf server listening on port 34143" Jan 25 22:52:42 volumio volumio[6140]: error: MPD error: The expression evaluated to a falsy value: Jan 25 22:52:42 volumio volumio[6140]: assert.ok(self.idling) Jan 25 22:52:42 volumio volumio[6140]: error: The expression evaluated to a falsy value: Jan 25 22:52:42 volumio volumio[6140]: assert.ok(self.idling) Jan 25 22:52:42 volumio volumio[6140]: error: updateQueue error: null Jan 25 22:52:42 volumio volumio[6140]: info: MPD running with PID6364 Jan 25 22:52:42 volumio volumio[6140]: ,establishing connection Jan 25 22:52:42 volumio volumio[6140]: info: Completed starting Core Plugins Jan 25 22:52:42 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:42 volumio volumio[6140]: info: ----- MyVolumio plugins startup ---- Jan 25 22:52:42 volumio volumio[6140]: info: ------------------------------------------- Jan 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+07:00" level=debug msg="obtained new client token: AABpr9D/Pi+kz+ZgCO09VbNGS0Q7M+DrXlwDUV+DYMvmWpp4GKmk9rhNgM2uk82AAzMPhWYi0HI32WdjWnJjcjl/HSIp1vpdZDYQcRnezoS25Y9qkMRbEHBosPKRXPKZQHNveca2ERACLaubflEhUN7W2sL+/01lfvA5bTandayXJkvSLoLlhBm9OdlhMJL//4NVKzzH6L48NpJwLag5hwFwW6lVDLrisxiBgby0AFZz4hgk13AoaKaDOyE=" Jan 25 22:52:42 volumio volumio[6140]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 25 22:52:42 volumio volumio[6140]: error: updateQueue error: null Jan 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:42 volumio go-librespot[6456]: time="2026-01-25T22:52:42+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 25 22:52:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:42 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:44 volumio volumio[6140]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:44 volumio volumio[6140]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:52:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:44 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 25 22:52:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:45 volumio go-librespot[6467]: go-librespot daemon starting... Jan 25 22:52:45 volumio go-librespot[6468]: time="2026-01-25T22:52:45+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:45 volumio go-librespot[6468]: time="2026-01-25T22:52:45+07:00" level=debug msg="app state loaded" Jan 25 22:52:45 volumio go-librespot[6468]: time="2026-01-25T22:52:45+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=info msg="zeroconf server listening on port 38391" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="obtained new client token: AAA8Qccu8J8/0g4x9oVKCkWi92myIv01jIJQ4remvXpjtoksgxrZNq4QbbKDugchSTt5iQu4/qAw8MPJtm5m1HOTxUgNaKbtRlkN4HS9z2LDTuFSBMtgiN6iFkngRtf2vCMdjtK0OzdnCEOmLjn9Dfi3m5O8p+6cGZCP/9aQ75NsYghhWnnWAS6/I1ydR9ssYpOHQvR/VQvUjFrPPuv2BjJwLjx/obH+3kUdRz0xSWn9+2KfKKBzI+5Y2wo=" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=debug msg="completed challenge" Jan 25 22:52:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:46 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:46 volumio go-librespot[6468]: time="2026-01-25T22:52:46+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:47 volumio volumio[6140]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 25 22:52:47 volumio volumio[6140]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:47 volumio volumio[6140]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 25 22:52:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:48 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 25 22:52:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:50 volumio go-librespot[6477]: go-librespot daemon starting... Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=debug msg="app state loaded" Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:50 volumio volumio[6140]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=debug msg="new websocket client" Jan 25 22:52:50 volumio volumio[6140]: info: Connection to go-librespot Websocket established Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+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 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+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 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=info msg="zeroconf server listening on port 44501" Jan 25 22:52:50 volumio go-librespot[6478]: time="2026-01-25T22:52:50+07:00" level=debug msg="obtained new client token: AAA6ELKJqkcf17xU8FAJfH6S5GN7SVwPVe3VBh9dJAkgaBZ52pWjJIvhmfhOnNEGYX0/LsvRiRllLL/pdcRMpk6WL8sTJDWvEbrbgbtMn8P0UCpss5/ng9dLiRG++qyGNW4wkaWSeXSzpSG0/x8QP9mNy3HP8vHimWj6iDgflKFnpIgnvxBDpFUvTzWwTejGvZDvukktOhgh2m5rs6yBfxyALy088fSaZL/OCwQvU1HrkNhDnD+DAJxcPbM=" Jan 25 22:52:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:50 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:51 volumio go-librespot[6478]: time="2026-01-25T22:52:51+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:51 volumio go-librespot[6478]: time="2026-01-25T22:52:51+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:51 volumio go-librespot[6478]: time="2026-01-25T22:52:51+07:00" level=debug msg="completed challenge" Jan 25 22:52:51 volumio go-librespot[6478]: time="2026-01-25T22:52:51+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:51 volumio volumio[6140]: info: Connection to go-librespot Websocket closed Jan 25 22:52:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin bluetooth to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin multiroom to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin metavolumio to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin cd_controller to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 25 22:52:51 volumio volumio[6140]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 25 22:52:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:52 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:53 volumio volumio[6140]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 25 22:52:53 volumio volumio[6140]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 25 22:52:53 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:53 volumio volumio[6140]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 25 22:52:53 volumio volumio[6140]: info: Starting MyVolumio Remote Streaming Endpoints Jan 25 22:52:53 volumio volumio[6140]: info: MyVolumio login type: Token Jan 25 22:52:53 volumio volumio[6140]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 25 22:52:53 volumio volumio[6140]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 25 22:52:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Jan 25 22:52:54 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:54 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 25 22:52:54 volumio go-librespot[6499]: go-librespot daemon starting... Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=info msg="running go-librespot 0.4.0" Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=debug msg="app state loaded" Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 25 22:52:54 volumio volumio[6140]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 25 22:52:54 volumio volumio[6140]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 25 22:52:54 volumio volumio[6140]: info: Streaming services startup Jan 25 22:52:54 volumio volumio[6140]: info: Starting Streaming Daemon Jan 25 22:52:54 volumio sudo[6508]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 25 22:52:54 volumio sudo[6508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 25 22:52:54 volumio volumio[6140]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 25 22:52:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:54 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 25 22:52:54 volumio sudo[6508]: pam_unix(sudo:session): session closed for user root Jan 25 22:52:54 volumio go-librespot[6500]: time="2026-01-25T22:52:54+07:00" level=info msg="zeroconf server listening on port 36407" Jan 25 22:52:54 volumio volumio[6140]: info: Getting Spotify volume Jan 25 22:52:55 volumio volumio[6140]: info: Initializing connection to go-librespot Websocket Jan 25 22:52:55 volumio volumio[6140]: error: Cannot start Volumio Streaming Daemon Jan 25 22:52:55 volumio volumio[6140]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 25 22:52:55 volumio volumio[6140]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=debug msg="new websocket client" Jan 25 22:52:55 volumio volumio[6140]: 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 25 22:52:55 volumio volumio[6140]: info: Connection to go-librespot Websocket established Jan 25 22:52:55 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:55 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=debug msg="obtained new client token: AAB4oX11lOB7gu77R78sZG7WnVZXajz35xgtVggEQV33/ho0K+Pb2Aho9WetsClXQhexRNujGfuGdFc346WtGjo14Mwx/rQ7DG76Z8LKb2PhgAAgt+GOwZGCerbivTvdp54g2KhSk0LLCICQ8iZ23s5FApr4mFfHGZn9F0y7GHDlF7NbEnJi0tKqnPzjO84hplrYvLGWYoaIYJ/6BDrmhMelbGbF6rKUnaPv0xx2yYlhL9AwVRQAtWb0" Jan 25 22:52:55 volumio volumio[6140]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 25 22:52:55 volumio volumio[6140]: SPOTIFY: SPOTIFY VOLUME undefined Jan 25 22:52:55 volumio volumio[6140]: SPOTIFY: VOLUMIO VOLUME 100 Jan 25 22:52:55 volumio volumio[6140]: info: Aligning Spotify Volume to Volumio Volume Jan 25 22:52:55 volumio volumio[6140]: info: CoreCommandRouter::volumioGetState Jan 25 22:52:55 volumio volumio[6140]: info: CorePlayQueue::getTrack 0 Jan 25 22:52:55 volumio volumio[6140]: info: Setting Spotify Volume from Volumio: 100 Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=debug msg="completed keyexchange" Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=debug msg="completed challenge" Jan 25 22:52:55 volumio go-librespot[6500]: time="2026-01-25T22:52:55+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 25 22:52:55 volumio volumio[6140]: info: Connection to go-librespot Websocket closed Jan 25 22:52:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 25 22:52:55 volumio volumio[6140]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:52:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 25 22:52:55 volumio volumio[6140]: Error: socket hang up Jan 25 22:52:55 volumio volumio[6140]: at connResetException (node:internal/errors:720:14) Jan 25 22:52:55 volumio volumio[6140]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 25 22:52:55 volumio volumio[6140]: at Socket.emit (node:events:526:35) Jan 25 22:52:55 volumio volumio[6140]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 25 22:52:55 volumio volumio[6140]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 25 22:52:55 volumio volumio[6140]: code: 'ECONNRESET', Jan 25 22:52:55 volumio volumio[6140]: response: undefined Jan 25 22:52:55 volumio volumio[6140]: } Jan 25 22:52:55 volumio volumio[6140]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 25 22:52:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 25 22:52:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 25 22:52:56 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 25 22:52:57 volumio sudo[6529]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-25 22:51' Jan 25 22:52:57 volumio sudo[6529]: 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"