Jan 28 16:50:00 volumio sudo[6296]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 28 16:50:00 volumio sudo[6296]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:00 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "wizard"... Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "networkfs"... Jan 28 16:50:00 volumio volumio[6251]: info: Starting Udev Watcher for removable devices Jan 28 16:50:00 volumio volumio[6251]: info: Ignoring mount for partition: boot Jan 28 16:50:00 volumio volumio[6251]: info: Ignoring mount for partition: volumio Jan 28 16:50:00 volumio volumio[6251]: info: Ignoring mount for partition: volumio_data Jan 28 16:50:00 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "volumio_command_line_client"... Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "upnp"... Jan 28 16:50:00 volumio volumio[6251]: info: [1769593800250] Starting Upmpd Daemon Jan 28 16:50:00 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "my_music"... Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "mpd"... Jan 28 16:50:00 volumio volumio[6251]: info: Loading plugin "upnp_browser"... Jan 28 16:50:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 28 16:50:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:01 volumio go-librespot[6319]: go-librespot daemon starting... Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=debug msg="app state loaded" Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50: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 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50: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 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50: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 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=info msg="zeroconf server listening on port 43449" Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=debug msg="obtained new client token: AACNKbSIivD/naSiMpyGn0I8OL1Zr+/E5Cu5cQZ7btltcD4vYtUm7toCtYeqxDr9DfJUoZ6aqBtnC1CZ8Kdxoz6IrIgqdV3zYBvKGaauviszJmwZM8ogGzRnf0nMS07nNcJAflF8IUoaQGLgR5deNqFSUhjgO5CbmFTg7tBBkP+5eq75VzuqopDCNU6pQgNWz20eM3YyewXwsyr9xFEL43lZF5LHDtTOp8ORSzuNDF3OYBw+PSrNk1Ek7kA=" Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Jan 28 16:50:01 volumio go-librespot[6320]: time="2026-01-28T16:50:01+07:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 28 16:50:02 volumio go-librespot[6320]: time="2026-01-28T16:50:02+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:02 volumio go-librespot[6320]: time="2026-01-28T16:50:02+07:00" level=debug msg="completed challenge" Jan 28 16:50:02 volumio go-librespot[6320]: time="2026-01-28T16:50: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 28 16:50:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:02 volumio sudo[6296]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:03 volumio volumio[6251]: info: Starting UPNP Browser Jan 28 16:50:03 volumio volumio[6251]: info: Loading plugin "alarm-clock"... Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "airplay_emulation"... Jan 28 16:50:04 volumio volumio[6251]: info: Starting Shairport Sync Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "last_100"... Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "webradio"... Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "i2s_dacs"... Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "volumiodiscovery"... Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** For more information see Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:04 volumio volumio[6251]: *** WARNING *** For more information see Jan 28 16:50:04 volumio node[6251]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:04 volumio node[6251]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:04 volumio node[6251]: *** WARNING *** For more information see Jan 28 16:50:04 volumio node[6251]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:04 volumio node[6251]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:04 volumio node[6251]: *** WARNING *** For more information see Jan 28 16:50:04 volumio volumio[6251]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 28 16:50:04 volumio volumio[6251]: info: Discovery: Started advertising with name: Volumio Jan 28 16:50:04 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:04 volumio volumio[6251]: info: Loading plugin "spop"... Jan 28 16:50:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 28 16:50:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:05 volumio go-librespot[6330]: go-librespot daemon starting... Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=debug msg="app state loaded" Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:05 volumio go-librespot[6331]: time="2026-01-28T16:50:05+07:00" level=info msg="zeroconf server listening on port 35831" Jan 28 16:50:06 volumio go-librespot[6331]: time="2026-01-28T16:50:06+07:00" level=debug msg="obtained new client token: AABZYYUDjRxy38E5EA4P8XNNixlsMlZN+R7/k8qg0CECj+Ty00DszBM0kMnBaImVR76HTVc5X/kpQ2VJcjuLRTtzGXJfEDNkVVCWy0l048LwgoJvtdxNtEFNlD+LDV5AY8TR7CZ7ffQ03zRofXW06vLSMFKZStShgoOZkmeAStz0+6kRPCeMNO1wWgjwhv83XC0JVJdhx58ppEcdHGIDTWR8llcEAKRr+lM8ymU2uWxdTIiE72WhFJrt" Jan 28 16:50:06 volumio go-librespot[6331]: time="2026-01-28T16:50:06+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:06 volumio go-librespot[6331]: time="2026-01-28T16:50:06+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:06 volumio go-librespot[6331]: time="2026-01-28T16:50:06+07:00" level=debug msg="completed challenge" Jan 28 16:50:06 volumio volumio[6251]: info: Loading plugin "ytcr"... Jan 28 16:50:06 volumio go-librespot[6331]: time="2026-01-28T16:50: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 28 16:50:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:09 volumio volumio[6251]: info: Loading plugin "ytmusic"... Jan 28 16:50:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 28 16:50:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:09 volumio go-librespot[6338]: go-librespot daemon starting... Jan 28 16:50:09 volumio go-librespot[6339]: time="2026-01-28T16:50:09+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:09 volumio go-librespot[6339]: time="2026-01-28T16:50:09+07:00" level=debug msg="app state loaded" Jan 28 16:50:09 volumio go-librespot[6339]: time="2026-01-28T16:50:09+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:10 volumio volumio-remote-updater[628]: [2026-01-28 16:50:10] [connect] Successful connection Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "outputs"... Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "albumart"... Jan 28 16:50:10 volumio volumio[6251]: info: Plugin example_plugin is not enabled Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "inputs"... Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "updater_comm"... Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50: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-gew1.spotify.com:80]" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=info msg="zeroconf server listening on port 39325" Jan 28 16:50:10 volumio volumio[6251]: info: Plugin mpdemulation is not enabled Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "rest_api"... Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "websocket"... Jan 28 16:50:10 volumio volumio[6251]: info: Starting Socket.io Server version 1.7.4 Jan 28 16:50:10 volumio volumio[6251]: info: Loading plugin "RoonBridge"... Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="obtained new client token: AABDoo3HCu7345lt0HoQH+ahJkX2zik6aq5CmzxoRU0MRYtN3Jw0Hzj6B0+tUwvoUW8HR74i3dgjFG5ayIpXzICJdId4xuyP3rjnjRMLtGgz7fGar9q2RE4wbJSwJxyxjoZKw+rE0ULksdBKu+H5JCEBhBGr/T9+tipcLH5ng1sXXf0kVc77tINBNjkkMNT+S1fxXyvsRl+kzZ6bvM3e0REX2R6fUpotRljb3U/T8VCyL9q6SP6BRs0Htuk=" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:10 volumio go-librespot[6339]: time="2026-01-28T16:50:10+07:00" level=debug msg="completed challenge" Jan 28 16:50:10 volumio volumio[6251]: info: Applying required configuration parameters for plugin RoonBridge Jan 28 16:50:11 volumio go-librespot[6339]: time="2026-01-28T16:50: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 28 16:50:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:11 volumio volumio[6251]: info: Loading i18n strings for locale en Jan 28 16:50:11 volumio volumio[6251]: Updating browse sources language Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::initPlayerControls Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:11 volumio volumio[6251]: Express server listening on port 3000 Jan 28 16:50:11 volumio volumio[6251]: [Metrics] WebUI: 15s 999.18ms Jan 28 16:50:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:11 volumio volumio[6251]: info: CoreStateMachine::resetVolumioState Jan 28 16:50:11 volumio volumio[6251]: info: CoreStateMachine::getcurrentVolume Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:50:11 volumio volumio[6360]: Forking 3 albumart workers Jan 28 16:50:11 volumio sudo[6375]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 16:50:11 volumio sudo[6375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:11 volumio sudo[6379]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 16:50:11 volumio sudo[6375]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:11 volumio sudo[6379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:11 volumio sudo[6379]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:11 volumio volumio[6251]: info: Volumio Network Manager: Network status updated: 1 Jan 28 16:50:11 volumio volumio[6251]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:50:11 volumio volumio[6251]: info: CoreStateMachine::pushState Jan 28 16:50:11 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:11 volumio volumio[6251]: info: CoreStateMachine::updateTrackBlock Jan 28 16:50:11 volumio volumio[6251]: info: CorePlayQueue::getTrackBlock Jan 28 16:50:11 volumio volumio[6251]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:50:11 volumio volumio-remote-updater[628]: [2026-01-28 16:50:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769593810 101 Jan 28 16:50:12 volumio volumio[6251]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:12 volumio volumio[6251]: info: Reloading queue from file Jan 28 16:50:12 volumio volumio[6251]: info: CoreStateMachine::setRepeat null single undefined Jan 28 16:50:12 volumio volumio[6251]: info: CoreStateMachine::pushState Jan 28 16:50:12 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:12 volumio volumio[6251]: info: CoreStateMachine::setRandom null Jan 28 16:50:12 volumio volumio[6251]: info: CoreStateMachine::pushState Jan 28 16:50:12 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:12 volumio volumio[6251]: info: Setting Device type: Raspberry PI Jan 28 16:50:12 volumio volumio[6251]: info: Completed loading Core Plugins Jan 28 16:50:12 volumio volumio[6251]: info: Preparing to generate the ALSA configuration file Jan 28 16:50:12 volumio volumio[6251]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:50:12 volumio volumio[6251]: info: CoreStateMachine::pushState Jan 28 16:50:12 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:12 volumio volumio[6251]: info: Asound.conf file unchanged, so no further update is needed Jan 28 16:50:12 volumio volumio[6251]: info: Output device has changed, restarting MPD Jan 28 16:50:12 volumio volumio[6251]: info: Output device has changed, restarting Shairport Sync Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:12 volumio sudo[6420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 28 16:50:12 volumio sudo[6420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:12 volumio sudo[6422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 16:50:12 volumio sudo[6422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:12 volumio sudo[6424]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 16:50:12 volumio sudo[6424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:12 volumio volumio[6251]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:12 volumio volumio[6251]: info: ___________ START PLUGINS ___________ Jan 28 16:50:12 volumio sudo[6422]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:12 volumio volumio[6251]: info: ControllerMpd::onStart: Initializing MPD Jan 28 16:50:12 volumio volumio[6251]: info: Creating MPD Configuration file Jan 28 16:50:12 volumio sudo[6433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:12 volumio sudo[6433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:12 volumio volumio[6251]: info: [1769593812668] CoreMusicLibrary::Adding element Media Servers Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:12 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 28 16:50:12 volumio sudo[6433]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:12 volumio sudo[6420]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:12 volumio volumio[6251]: info: UPNP Browser: Client initialized successfully Jan 28 16:50:12 volumio sudo[6435]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 16:50:12 volumio sudo[6435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:12 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 16:50:12 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 16:50:12 volumio systemd[1]: mpd.service: Consumed 7.139s CPU time. Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:12 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 16:50:12 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 16:50:12 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 16:50:12 volumio volumio[6251]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:12 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:12 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 16:50:12 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 16:50:13 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 16:50:13 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 16:50:13 volumio volumio[6251]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:13 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 16:50:13 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 16:50:13 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:13 volumio volumio[6251]: info: [1769593813053] CoreMusicLibrary::Adding element Last_100 Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:13 volumio volumio[6251]: info: [1769593813061] CoreMusicLibrary::Adding element Webradio Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:13 volumio volumio[6251]: info: Initializing BBC Radios Jan 28 16:50:13 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 16:50:13 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:13 volumio volumio[6251]: info: Creating Spotify config file Jan 28 16:50:13 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:13 volumio sudo[6452]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 28 16:50:13 volumio sudo[6452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 28 16:50:13 volumio sudo[6452]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 28 16:50:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:14 volumio go-librespot[6465]: go-librespot daemon starting... Jan 28 16:50:14 volumio go-librespot[6466]: time="2026-01-28T16:50:14+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:14 volumio volumio[6251]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:14 volumio volumio[6251]: info: [1769593814541] CoreMusicLibrary::Adding element YouTube Music Jan 28 16:50:14 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:14 volumio volumio[6378]: Starting albumart workers Jan 28 16:50:14 volumio volumio[6251]: Cannot find translation for source YouTube Music Jan 28 16:50:14 volumio volumio[6251]: info: Volumio Calling Home Jan 28 16:50:14 volumio sudo[6473]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 28 16:50:14 volumio sudo[6473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:14 volumio sudo[6473]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:15 volumio volumio[6380]: Starting albumart workers Jan 28 16:50:15 volumio volumio[6376]: Starting albumart workers Jan 28 16:50:15 volumio go-librespot[6466]: time="2026-01-28T16:50:15+07:00" level=info msg="zeroconf server listening on port 34109" Jan 28 16:50:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:15 volumio volumio[6251]: info: MPD Permissions set Jan 28 16:50:15 volumio volumio[6251]: info: MPD Permissions set Jan 28 16:50:15 volumio volumio[6251]: info: Upmpdcli Daemon Started Jan 28 16:50:15 volumio volumio[6251]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 16:50:15 volumio volumio[6251]: info: Discovery: Found device Volumio Jan 28 16:50:15 volumio volumio[6251]: info: CoreCommandRouter::volumioGetState Jan 28 16:50:15 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:16 volumio volumio[6251]: info: Volumio called home Jan 28 16:50:16 volumio volumio[6251]: info: Spotify config file written Jan 28 16:50:16 volumio volumio[6251]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 16:50:16 volumio volumio[6251]: info: Discovery: Found device Volumio Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::volumioGetState Jan 28 16:50:16 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:16 volumio sudo[6480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 16:50:16 volumio sudo[6480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:16 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 16:50:16 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 16:50:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:16 volumio volumio[6251]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:16 volumio go-librespot[6482]: go-librespot daemon starting... Jan 28 16:50:16 volumio sudo[6480]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio go-librespot[6488]: time="2026-01-28T16:50:16+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:16 volumio go-librespot[6488]: time="2026-01-28T16:50:16+07:00" level=debug msg="app state loaded" Jan 28 16:50:16 volumio go-librespot[6488]: time="2026-01-28T16:50:16+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:16 volumio volumio[6251]: info: No need to fix Spotify hosts Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=info msg="zeroconf server listening on port 40925" Jan 28 16:50:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="obtained new client token: AABOh8ho588d7CjWhUIXdAUZd2OcUDdZve2g2ASEbwfqefrhtEVkQEJkKGwkKaljA1ChOaRmez0xOc4LKi6Y+k5syyrBYTO+cL9fSkpgAxAWCSNa0xczq28+PrvVh1/iZ0ZJoD6gsFBc2M5zHQK9o8cTvU5wUTs/e/zmK0yDZcGSAzJzvixd9Jti84pQJtxm5FUVLk+Tnm4YxbJrQ/sTfizQS6zWvvG3lJie2FbAGhJdb5rpOsVJX+DJckg=" Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:17 volumio volumio[6251]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 16:50:17 volumio volumio[6251]: SPOTIFY: BQBsolSEE1scd9jdgy5PcTL6YapV4BP_YpSxf6tMguPGXQNWWGEoaywoe-RCmzV3S4WrdU3UchHjEdZrGvSUb7PTnCUelR8FHdnQZtwk80BuEH0YYFCSwymS4zm72pE5BzhBiJWQe4t5wDmgStnntG0Iimc_v18VB2bs1fzL2DIgQZjj-gxFPGLRomNX0dEEcObsSAmbqIZZ5JOj6aOJIphQxijO9pydD8N_NpFqtDG3UXNg8bl7-amxNFeTXjtR7AwE6eYvh8SrIjJ2fx44SqGiML7GfJGPkyMl4f8KhTEkqyNPN7CPyqHE Jan 28 16:50:17 volumio volumio[6251]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 16:50:17 volumio volumio[6251]: info: New Spotify access token = BQBsolSEE1scd9jdgy5PcTL6YapV4BP_YpSxf6tMguPGXQNWWGEoaywoe-RCmzV3S4WrdU3UchHjEdZrGvSUb7PTnCUelR8FHdnQZtwk80BuEH0YYFCSwymS4zm72pE5BzhBiJWQe4t5wDmgStnntG0Iimc_v18VB2bs1fzL2DIgQZjj-gxFPGLRomNX0dEEcObsSAmbqIZZ5JOj6aOJIphQxijO9pydD8N_NpFqtDG3UXNg8bl7-amxNFeTXjtR7AwE6eYvh8SrIjJ2fx44SqGiML7GfJGPkyMl4f8KhTEkqyNPN7CPyqHE Jan 28 16:50:17 volumio volumio[6251]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=debug msg="completed challenge" Jan 28 16:50:17 volumio volumio[6251]: info: Starting Shairport Sync Jan 28 16:50:17 volumio volumio[6251]: info: Starting Shairport Sync Jan 28 16:50:17 volumio volumio[6251]: info: Starting Shairport Sync Jan 28 16:50:17 volumio go-librespot[6488]: time="2026-01-28T16:50:17+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:17 volumio sudo[6520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:50:17 volumio sudo[6520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:17 volumio sudo[6524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:50:17 volumio sudo[6524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:17 volumio sudo[6522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:50:17 volumio sudo[6522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:18 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 16:50:18 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 16:50:18 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 16:50:18 volumio systemd[1]: shairport-sync.service: Consumed 2.338s CPU time. Jan 28 16:50:18 volumio volumio[6251]: info: CoreCommandRouter::volumioGetState Jan 28 16:50:18 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:18 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 16:50:18 volumio sudo[6520]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:18 volumio sudo[6524]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:18 volumio sudo[6522]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:18 volumio volumio[6251]: info: Shairport-Sync Started Jan 28 16:50:18 volumio volumio[6251]: Error adding Membership: Error: addMembership EINVAL Jan 28 16:50:18 volumio volumio[6251]: info: Shairport-Sync Started Jan 28 16:50:18 volumio volumio[6251]: info: Shairport-Sync Started Jan 28 16:50:18 volumio volumio[6251]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 28 16:50:18 volumio volumio[6251]: info: Spotify Successfully logged in Jan 28 16:50:18 volumio volumio[6251]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:18 volumio volumio[6251]: info: [1769593818568] CoreMusicLibrary::Adding element Spotify Jan 28 16:50:18 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:18 volumio volumio[6251]: Cannot find translation for source YouTube Music Jan 28 16:50:18 volumio volumio[6251]: Cannot find translation for source Spotify Jan 28 16:50:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:20 volumio mpd[6464]: 2026-01-28T16:50:20 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 28 16:50:20 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 28 16:50:20 volumio sudo[6435]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:20 volumio sudo[6424]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:20 volumio volumio[6251]: error: MPD error: The expression evaluated to a falsy value: Jan 28 16:50:20 volumio volumio[6251]: assert.ok(self.idling) Jan 28 16:50:20 volumio volumio[6251]: error: The expression evaluated to a falsy value: Jan 28 16:50:20 volumio volumio[6251]: assert.ok(self.idling) Jan 28 16:50:20 volumio volumio[6251]: info: go-librespot daemon successfully initialized Jan 28 16:50:20 volumio volumio[6251]: error: updateQueue error: null Jan 28 16:50:20 volumio volumio[6251]: info: MPD running with PID6464 Jan 28 16:50:20 volumio volumio[6251]: ,establishing connection Jan 28 16:50:20 volumio volumio[6251]: error: updateQueue error: null Jan 28 16:50:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 16:50:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:21 volumio go-librespot[6563]: go-librespot daemon starting... Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="app state loaded" Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=info msg="zeroconf server listening on port 40139" Jan 28 16:50:21 volumio volumio[6251]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 28 16:50:21 volumio volumio[6251]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="obtained new client token: AAABFizXr0F1uRYSNAC/X8WdJHzzG9Nu5LRwBL/GwxVfU02F6xgLr/W/+MGcUX4Nwjf4qQWoRXwPun54mD3Z8Ix1KjWQDNNoX+hnJ+kEBB729HNhHzXQ/0unSz+yD22pjwyuFTLDEBjvlyYY6QqkHpoeL0JUbz3Ec1waJVx5RRXlAq+Frge2XNIVFYuAHrDpbWSv83qSDp64NYeGlFfoRv5NQ8S+Ttjlt+4I9BWrHBLvbGRjTukeuceNMG8=" Jan 28 16:50:21 volumio volumio[6251]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:50:21 volumio volumio[6251]: info: CoreCommandRouter::volumioGetState Jan 28 16:50:21 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:21 volumio volumio[6251]: info: CoreStateMachine::pushState Jan 28 16:50:21 volumio volumio[6251]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:21 volumio volumio[6251]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:21 volumio go-librespot[6564]: time="2026-01-28T16:50:21+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:22 volumio go-librespot[6564]: time="2026-01-28T16:50:22+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:22 volumio go-librespot[6564]: time="2026-01-28T16:50:22+07:00" level=debug msg="completed challenge" Jan 28 16:50:22 volumio volumio[6251]: info: Completed starting Core Plugins Jan 28 16:50:22 volumio volumio[6251]: info: ------------------------------------------- Jan 28 16:50:22 volumio volumio[6251]: info: ----- MyVolumio plugins startup ---- Jan 28 16:50:22 volumio volumio[6251]: info: ------------------------------------------- Jan 28 16:50:22 volumio volumio[6251]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 28 16:50:22 volumio go-librespot[6564]: time="2026-01-28T16:50:22+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:23 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:23 volumio volumio[6251]: info: Initializing connection to go-librespot Websocket Jan 28 16:50:23 volumio volumio[6251]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 16:50:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 28 16:50:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:25 volumio go-librespot[6574]: go-librespot daemon starting... Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=debug msg="app state loaded" Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:25 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:25 volumio volumio[6251]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:25 volumio go-librespot[6575]: time="2026-01-28T16:50:25+07:00" level=info msg="zeroconf server listening on port 45371" Jan 28 16:50:26 volumio go-librespot[6575]: time="2026-01-28T16:50:26+07:00" level=debug msg="obtained new client token: AAA+kCWMfkuxcrYIq1P0YxRf/YLvU6+q5F8FDGsoGaZHjiVUWXvrr32xb61QjCTQY5shIClsSM1KdDD8gMLaykKUjJXMsyXhKekt/Jx0Yn/aBUthjWK7p4DReLp/7sr36HNctIxzr8PG6TRaAZYqZXmdAem9Pizh+nzwKi+8BuOvLmwhjM5v6HUNEMxHGuiazBB84bT+UPH4SWWaKikqtquTfa9Gel5IQfRlfO/Qz4OXbARFtHmSuajY" Jan 28 16:50:26 volumio go-librespot[6575]: time="2026-01-28T16:50:26+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:26 volumio go-librespot[6575]: time="2026-01-28T16:50:26+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:26 volumio go-librespot[6575]: time="2026-01-28T16:50:26+07:00" level=debug msg="completed challenge" Jan 28 16:50:26 volumio go-librespot[6575]: time="2026-01-28T16:50:26+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:26 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jan 28 16:50:26 volumio volumio[6251]: info: Initializing connection to go-librespot Websocket Jan 28 16:50:26 volumio volumio[6251]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 16:50:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:27 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:28 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Jan 28 16:50:28 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jan 28 16:50:28 volumio systemd[1]: setdatetime-helper.service: Consumed 1.741s CPU time. Jan 28 16:50:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:29 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 28 16:50:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:29 volumio go-librespot[6607]: go-librespot daemon starting... Jan 28 16:50:29 volumio go-librespot[6608]: time="2026-01-28T16:50:29+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:29 volumio go-librespot[6608]: time="2026-01-28T16:50:29+07:00" level=debug msg="app state loaded" Jan 28 16:50:29 volumio go-librespot[6608]: time="2026-01-28T16:50:29+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:29 volumio volumio[6251]: info: Initializing connection to go-librespot Websocket Jan 28 16:50:29 volumio go-librespot[6608]: time="2026-01-28T16:50:29+07:00" level=debug msg="new websocket client" Jan 28 16:50:29 volumio volumio[6251]: info: Connection to go-librespot Websocket established Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=info msg="zeroconf server listening on port 42923" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="obtained new client token: AAATDi/E9ShpA2J7pv8N7x9T3Pg60agn/swNR4OlFE0jOE8ZAQF0ql8mGAYs8cW1XwDRCboegSWKw71j6p6wsoUjE3SXIl5fmrrJAqjph4z9+Me5p58bjSGmubZDGDXRL2BZltJu/5mPTp+8UUnfZva4kgZ4Z5z19nsQSFS36PDVGIdX+fIC6Ra3L/ZWXmGUA3JwX8Xp9xR0e7xd4yO5M9KiDR3cYiFjHDivu/pisWQkm2hjgmc+oY8J" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=debug msg="completed challenge" Jan 28 16:50:30 volumio go-librespot[6608]: time="2026-01-28T16:50:30+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:30 volumio volumio[6251]: info: Connection to go-librespot Websocket closed Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin bluetooth to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin multiroom to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin metavolumio to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin cd_controller to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 28 16:50:30 volumio volumio[6251]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 28 16:50:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:31 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:32 volumio volumio[6251]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 28 16:50:32 volumio volumio[6251]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 28 16:50:32 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:32 volumio volumio[6251]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:32 volumio volumio[6251]: info: Starting MyVolumio Remote Streaming Endpoints Jan 28 16:50:32 volumio volumio[6251]: info: MyVolumio login type: Token Jan 28 16:50:32 volumio volumio[6251]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 28 16:50:32 volumio volumio[6251]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 28 16:50:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:33 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 28 16:50:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:33 volumio go-librespot[6629]: go-librespot daemon starting... Jan 28 16:50:33 volumio go-librespot[6630]: time="2026-01-28T16:50:33+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:33 volumio go-librespot[6630]: time="2026-01-28T16:50:33+07:00" level=debug msg="app state loaded" Jan 28 16:50:33 volumio go-librespot[6630]: time="2026-01-28T16:50:33+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=info msg="zeroconf server listening on port 45541" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="obtained new client token: AABu93oiOKsdEykNwB2G2pNzEpEVtB3KXx/oN1WRo2BeMaUzftUHt+QFCv668L8NdBC6zLtXZ890KfwC0aY719JbDAMnb1kjl6e724ypFjmnNCehU1EmP7QdXHxq57jRNkK2IkNm0ppxFvgnZbGISZkqhzS5oDUXdeKF8GVYPn/fZW85qpGuJjwS7L4xLaoRQc2J33RvfHImtxEhhGJ4LXyEXb9XaEdOtXqIfhy2AulHoa7yVULrScega+o=" Jan 28 16:50:34 volumio volumio[6251]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 28 16:50:34 volumio volumio[6251]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 28 16:50:34 volumio volumio[6251]: info: Streaming services startup Jan 28 16:50:34 volumio volumio[6251]: info: Starting Streaming Daemon Jan 28 16:50:34 volumio sudo[6638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 28 16:50:34 volumio sudo[6638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:34 volumio volumio[6251]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:34 volumio sudo[6638]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50:34+07:00" level=debug msg="completed challenge" Jan 28 16:50:34 volumio volumio[6251]: info: Getting Spotify volume Jan 28 16:50:34 volumio volumio[6251]: info: Initializing connection to go-librespot Websocket Jan 28 16:50:34 volumio volumio[6251]: error: Cannot start Volumio Streaming Daemon Jan 28 16:50:34 volumio volumio[6251]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 28 16:50:34 volumio volumio[6251]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 28 16:50:34 volumio go-librespot[6630]: time="2026-01-28T16:50: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 28 16:50:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:34 volumio volumio[6251]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 28 16:50:34 volumio volumio[6251]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Jan 28 16:50:34 volumio volumio[6251]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 16:50:34 volumio volumio[6251]: Error: socket hang up Jan 28 16:50:34 volumio volumio[6251]: at connResetException (node:internal/errors:720:14) Jan 28 16:50:34 volumio volumio[6251]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 28 16:50:34 volumio volumio[6251]: at Socket.emit (node:events:526:35) Jan 28 16:50:34 volumio volumio[6251]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 28 16:50:34 volumio volumio[6251]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 28 16:50:34 volumio volumio[6251]: code: 'ECONNRESET', Jan 28 16:50:34 volumio volumio[6251]: response: undefined Jan 28 16:50:34 volumio volumio[6251]: } Jan 28 16:50:34 volumio volumio[6251]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 16:50:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:35 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:36 volumio sudo[6660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 16:49' Jan 28 16:50:36 volumio sudo[6660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:36 volumio sudo[6660]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:36 volumio volumio-remote-updater[628]: [2026-01-28 16:50:36] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 28 16:50:36 volumio volumio-remote-updater[628]: [2026-01-28 16:50:36] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 28 16:50:36 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:36 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 28 16:50:36 volumio systemd[1]: volumio.service: Consumed 58.191s CPU time. Jan 28 16:50:36 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 16:50:37 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 16:50:37 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10414. Jan 28 16:50:37 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 28 16:50:37 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 28 16:50:37 volumio systemd[1]: volumio.service: Consumed 58.191s CPU time. Jan 28 16:50:37 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 28 16:50:37 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 28 16:50:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:37 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 28 16:50:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:38 volumio go-librespot[6693]: go-librespot daemon starting... Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=debug msg="app state loaded" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=info msg="zeroconf server listening on port 38403" Jan 28 16:50:38 volumio go-librespot[6694]: time="2026-01-28T16:50:38+07:00" level=debug msg="obtained new client token: AAC7UTfDwIjZOWw23ryG5cXoSCj2TG9PABanTVpJw0q95vzr9k2xQoa8SWLf/E9rwyFoGzxcw1sENMOhtsw9x051OOz7BrUYCwDrpSdpECCeDjeULj1dvcXtSZtF+rhUZSaLSgY7Dt47Ydmc0zSeVBtzQ6zMOM9Y/1y8azHQzGAainkEOvAVh0GJYwtmo480KH1TeOelUyRptRJ9jdAqb8O7jK4Ur+jioeUsH993FrbjsWP/lCWMNW1L990=" Jan 28 16:50:39 volumio go-librespot[6694]: time="2026-01-28T16:50:39+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:39 volumio go-librespot[6694]: time="2026-01-28T16:50:39+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:39 volumio go-librespot[6694]: time="2026-01-28T16:50:39+07:00" level=debug msg="completed challenge" Jan 28 16:50:39 volumio go-librespot[6694]: time="2026-01-28T16:50:39+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:39 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:40 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:50:40 volumio volumio[6678]: info: ----- Volumio3 ---- Jan 28 16:50:40 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:50:40 volumio volumio[6678]: info: ----- System startup ---- Jan 28 16:50:40 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:50:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:41 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:41 volumio volumio-remote-updater[628]: [2026-01-28 16:50:41] [connect] Successful connection Jan 28 16:50:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 28 16:50:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:42 volumio volumio[6678]: info: MYVOLUMIO Environment detected Jan 28 16:50:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:42 volumio go-librespot[6709]: go-librespot daemon starting... Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=debug msg="app state loaded" Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:42 volumio volumio[6678]: info: Plugin folders cleanup Jan 28 16:50:42 volumio volumio[6678]: info: Scanning into folder /volumio/app/plugins/ Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category audio_interface Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category miscellanea Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category music_service Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category plugins.json Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category system_controller Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category user_interface Jan 28 16:50:42 volumio volumio[6678]: info: Scanning into folder /data/plugins/ Jan 28 16:50:42 volumio volumio[6678]: info: Scanning category music_service Jan 28 16:50:42 volumio volumio[6678]: info: Plugin folders cleanup completed Jan 28 16:50:42 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:50:42 volumio volumio[6678]: info: ----- Core plugins startup ---- Jan 28 16:50:42 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:50:42 volumio volumio[6678]: info: Loading plugins from folder /volumio/app/plugins/ Jan 28 16:50:42 volumio volumio[6678]: info: Adding plugin upnp to MyMusic Plugins Jan 28 16:50:42 volumio volumio[6678]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 28 16:50:42 volumio volumio[6678]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 28 16:50:42 volumio volumio[6678]: info: Loading plugins from folder /data/plugins/ Jan 28 16:50:42 volumio volumio[6678]: info: Loading plugin "system"... Jan 28 16:50:42 volumio volumio[6678]: info: Loading plugin "appearance"... Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:42 volumio go-librespot[6713]: time="2026-01-28T16:50:42+07:00" level=info msg="zeroconf server listening on port 37809" Jan 28 16:50:43 volumio go-librespot[6713]: time="2026-01-28T16:50:43+07:00" level=debug msg="obtained new client token: AAAnxDjil/4MeB5AzDv+3WsrIIDUlItFWqsOQoFyfegIZ44y5crvAD9z3XY/9PPEzJrUbNbr1QdgmbYGdJ4RU9kSSfKgw1b6cIkGYB+vBPU/s3EQgNc28Yp9oMHQYRdptsyLF5A/37bZ9fDWKAtHSXGJ7gUpISaFSWTMk4LD1cxl9rpYA9JvawsXoN39Ok+4KJNFw/dDxX7MU9cRnsMjLyKwSzDLFdhf7qQuODarzIvC4W1baNZLmn6/" Jan 28 16:50:43 volumio go-librespot[6713]: time="2026-01-28T16:50:43+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:43 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:43 volumio go-librespot[6713]: time="2026-01-28T16:50:43+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:43 volumio go-librespot[6713]: time="2026-01-28T16:50:43+07:00" level=debug msg="completed challenge" Jan 28 16:50:43 volumio go-librespot[6713]: time="2026-01-28T16:50:43+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "network"... Jan 28 16:50:44 volumio volumio[6678]: info: Refreshing Cached IP Addresses Jan 28 16:50:44 volumio sudo[6724]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 16:50:44 volumio sudo[6724]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:44 volumio sudo[6726]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 16:50:44 volumio sudo[6726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:44 volumio sudo[6724]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:44 volumio sudo[6726]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "services"... Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "alsa_controller"... Jan 28 16:50:44 volumio sudo[6734]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 28 16:50:44 volumio sudo[6734]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:44 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "wizard"... Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "networkfs"... Jan 28 16:50:44 volumio volumio[6678]: info: Starting Udev Watcher for removable devices Jan 28 16:50:44 volumio volumio[6678]: info: Ignoring mount for partition: boot Jan 28 16:50:44 volumio volumio[6678]: info: Ignoring mount for partition: volumio Jan 28 16:50:44 volumio volumio[6678]: info: Ignoring mount for partition: volumio_data Jan 28 16:50:44 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "volumio_command_line_client"... Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "upnp"... Jan 28 16:50:44 volumio volumio[6678]: info: [1769593844904] Starting Upmpd Daemon Jan 28 16:50:44 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "my_music"... Jan 28 16:50:44 volumio volumio[6678]: info: Loading plugin "mpd"... Jan 28 16:50:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:45 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:45 volumio volumio[6678]: info: Loading plugin "upnp_browser"... Jan 28 16:50:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 28 16:50:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:46 volumio go-librespot[6757]: go-librespot daemon starting... Jan 28 16:50:46 volumio go-librespot[6758]: time="2026-01-28T16:50:46+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:46 volumio go-librespot[6758]: time="2026-01-28T16:50:46+07:00" level=debug msg="app state loaded" Jan 28 16:50:46 volumio go-librespot[6758]: time="2026-01-28T16:50:46+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=info msg="zeroconf server listening on port 33611" Jan 28 16:50:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:47 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:47 volumio sudo[6734]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="obtained new client token: AACbWRgvEq5Aj8U0/zp9r3GkAI3VkWYgmokNkC7T5tPMP75Hc7vY5dGl/P5IEqHAOZp/LIBrKeXz5EGl5qbmvLDEqMBXtk7rsTcp2PYMcRXRdXga2KeitDlGK8v4SviRip0/E7a/74XaFvnLD+qqjb9GkSm2Lxm8AXR+g7vIrBQJVtOadsBh4QKSWNDTEq+oyOa0AqZhwe4VghD4SD9Q6WO5Wve7ot10hJpX1t3GkIWxi5wFObCDeFLA8X8=" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=debug msg="completed challenge" Jan 28 16:50:47 volumio go-librespot[6758]: time="2026-01-28T16:50:47+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:48 volumio volumio[6678]: info: Starting UPNP Browser Jan 28 16:50:48 volumio volumio[6678]: info: Loading plugin "alarm-clock"... Jan 28 16:50:48 volumio volumio[6678]: info: Loading plugin "airplay_emulation"... Jan 28 16:50:48 volumio volumio[6678]: info: Starting Shairport Sync Jan 28 16:50:48 volumio volumio[6678]: info: Loading plugin "last_100"... Jan 28 16:50:48 volumio volumio[6678]: info: Loading plugin "webradio"... Jan 28 16:50:49 volumio volumio[6678]: info: Loading plugin "i2s_dacs"... Jan 28 16:50:49 volumio volumio[6678]: info: Loading plugin "volumiodiscovery"... Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:49 volumio node[6678]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** For more information see Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:49 volumio volumio[6678]: *** WARNING *** For more information see Jan 28 16:50:49 volumio node[6678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:49 volumio node[6678]: *** WARNING *** For more information see Jan 28 16:50:49 volumio node[6678]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 28 16:50:49 volumio node[6678]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 28 16:50:49 volumio node[6678]: *** WARNING *** For more information see Jan 28 16:50:49 volumio volumio[6678]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 28 16:50:49 volumio volumio[6678]: info: Discovery: Started advertising with name: Volumio Jan 28 16:50:49 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 28 16:50:49 volumio volumio[6678]: info: Loading plugin "spop"... Jan 28 16:50:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:49 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 28 16:50:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:51 volumio go-librespot[6768]: go-librespot daemon starting... Jan 28 16:50:51 volumio volumio[6678]: info: Loading plugin "ytcr"... Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=debug msg="app state loaded" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:51 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=info msg="zeroconf server listening on port 41527" Jan 28 16:50:51 volumio go-librespot[6769]: time="2026-01-28T16:50:51+07:00" level=debug msg="obtained new client token: AADFEK5CunYCb0YPzDlI8wcfOzuwnm1aZVY4MmcT4TpnSUoutKZid9MuFsIVC7rvcbETbUzXneveTyKYQOKGo2Z3W51BC6sDyA80SoqNGR6IKxSVfuebEmbzeJAqHLXdZiNVEGO3oRa3ZWc8Iee32+sfwH31lTJ3aR6FlzOC8BBiq1UQVCHxltt8i9l8u1Fda9ndxclU6sUK4RJNa1mtlL+sb3iZk+jdZ2tM6BC7ApDQcami7IdlsZaT5wk=" Jan 28 16:50:52 volumio go-librespot[6769]: time="2026-01-28T16:50:52+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:52 volumio go-librespot[6769]: time="2026-01-28T16:50:52+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:52 volumio go-librespot[6769]: time="2026-01-28T16:50:52+07:00" level=debug msg="completed challenge" Jan 28 16:50:52 volumio go-librespot[6769]: time="2026-01-28T16:50:52+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:53 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:53 volumio volumio[6678]: info: Loading plugin "ytmusic"... Jan 28 16:50:54 volumio volumio-remote-updater[628]: [2026-01-28 16:50:54] [connect] Successful connection Jan 28 16:50:54 volumio volumio[6678]: info: Loading plugin "outputs"... Jan 28 16:50:54 volumio volumio[6678]: info: Loading plugin "albumart"... Jan 28 16:50:54 volumio volumio[6678]: info: Plugin example_plugin is not enabled Jan 28 16:50:54 volumio volumio[6678]: info: Loading plugin "inputs"... Jan 28 16:50:54 volumio volumio[6678]: info: Loading plugin "updater_comm"... Jan 28 16:50:55 volumio volumio[6678]: info: Plugin mpdemulation is not enabled Jan 28 16:50:55 volumio volumio[6678]: info: Loading plugin "rest_api"... Jan 28 16:50:55 volumio volumio[6678]: info: Loading plugin "websocket"... Jan 28 16:50:55 volumio volumio[6678]: info: Starting Socket.io Server version 1.7.4 Jan 28 16:50:55 volumio volumio[6678]: info: Loading plugin "RoonBridge"... Jan 28 16:50:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:55 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 28 16:50:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:55 volumio go-librespot[6801]: go-librespot daemon starting... Jan 28 16:50:55 volumio go-librespot[6802]: time="2026-01-28T16:50:55+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:55 volumio go-librespot[6802]: time="2026-01-28T16:50:55+07:00" level=debug msg="app state loaded" Jan 28 16:50:55 volumio go-librespot[6802]: time="2026-01-28T16:50:55+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:50:55 volumio volumio[6678]: info: Applying required configuration parameters for plugin RoonBridge Jan 28 16:50:55 volumio volumio[6678]: info: Loading i18n strings for locale en Jan 28 16:50:55 volumio volumio[6678]: Updating browse sources language Jan 28 16:50:55 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:56 volumio volumio[6791]: Forking 3 albumart workers Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::initPlayerControls Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=info msg="zeroconf server listening on port 43755" Jan 28 16:50:56 volumio volumio[6678]: Express server listening on port 3000 Jan 28 16:50:56 volumio volumio[6678]: [Metrics] WebUI: 16s 199.51ms Jan 28 16:50:56 volumio volumio[6678]: info: CoreStateMachine::resetVolumioState Jan 28 16:50:56 volumio volumio[6678]: info: CoreStateMachine::getcurrentVolume Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="obtained new client token: AACie77sUrrU3NDh8wweMK4ZYPt6nsDLMHO5WWfDpkNEPpNf/uE5H+JdZ65PBLBZ+TNa33w0glIpykYyfLG+9rUVf0OuF3oaoXFwPp+txDlzvbPHFjfksXrYMleV4ott3kzHjtvHKE6QmgMKyrrnRnFW3XF9GQA58KkI5b5/lfEF+pcmX1mJB+nt21rdHx/vKPWU6NFCNO9Y0AJtud8JrZ8mNOb/rT3iS1tnZ+MX1clV7NvMZolFwcexGt4=" Jan 28 16:50:56 volumio sudo[6844]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 28 16:50:56 volumio sudo[6844]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:56 volumio sudo[6844]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:56 volumio sudo[6841]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 28 16:50:56 volumio sudo[6841]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:50:56 volumio sudo[6841]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:56 volumio volumio[6678]: info: Volumio Network Manager: Network status updated: 1 Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="completed keyexchange" Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=debug msg="completed challenge" Jan 28 16:50:56 volumio go-librespot[6802]: time="2026-01-28T16:50:56+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jan 28 16:50:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:50:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:50:56 volumio volumio[6678]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:50:56 volumio volumio[6678]: info: CoreStateMachine::pushState Jan 28 16:50:56 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:56 volumio volumio[6678]: info: CoreStateMachine::updateTrackBlock Jan 28 16:50:56 volumio volumio[6678]: info: CorePlayQueue::getTrackBlock Jan 28 16:50:56 volumio volumio[6678]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:50:56 volumio volumio-remote-updater[628]: [2026-01-28 16:50:56] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1769593854 101 Jan 28 16:50:57 volumio volumio[6678]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:57 volumio volumio[6678]: info: Reloading queue from file Jan 28 16:50:57 volumio volumio[6678]: info: CoreStateMachine::setRepeat null single undefined Jan 28 16:50:57 volumio volumio[6678]: info: CoreStateMachine::pushState Jan 28 16:50:57 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:57 volumio volumio[6678]: info: CoreStateMachine::setRandom null Jan 28 16:50:57 volumio volumio[6678]: info: CoreStateMachine::pushState Jan 28 16:50:57 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:57 volumio volumio[6678]: info: Setting Device type: Raspberry PI Jan 28 16:50:57 volumio volumio[6678]: info: Completed loading Core Plugins Jan 28 16:50:57 volumio volumio[6678]: info: Preparing to generate the ALSA configuration file Jan 28 16:50:57 volumio volumio[6678]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:50:57 volumio volumio[6678]: info: CoreStateMachine::pushState Jan 28 16:50:57 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::volumioPushState Jan 28 16:50:57 volumio volumio[6678]: info: Asound.conf file unchanged, so no further update is needed Jan 28 16:50:57 volumio volumio[6678]: info: Output device has changed, restarting MPD Jan 28 16:50:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:57 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:57 volumio volumio[6678]: info: Output device has changed, restarting Shairport Sync Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:57 volumio sudo[6859]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 28 16:50:57 volumio sudo[6859]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:57 volumio sudo[6861]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 16:50:57 volumio sudo[6861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:57 volumio sudo[6861]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:57 volumio volumio[6678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:57 volumio volumio[6678]: info: ___________ START PLUGINS ___________ Jan 28 16:50:57 volumio sudo[6863]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 16:50:57 volumio sudo[6863]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:57 volumio volumio[6678]: info: ControllerMpd::onStart: Initializing MPD Jan 28 16:50:57 volumio volumio[6678]: info: Creating MPD Configuration file Jan 28 16:50:57 volumio sudo[6859]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:57 volumio volumio[6678]: info: [1769593857687] CoreMusicLibrary::Adding element Media Servers Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:57 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 28 16:50:57 volumio sudo[6874]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 28 16:50:57 volumio sudo[6874]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:57 volumio sudo[6872]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 28 16:50:57 volumio sudo[6872]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:57 volumio volumio[6678]: info: UPNP Browser: Client initialized successfully Jan 28 16:50:57 volumio sudo[6872]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:57 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 16:50:57 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 16:50:57 volumio systemd[1]: mpd.service: Consumed 7.104s CPU time. Jan 28 16:50:57 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 16:50:57 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 16:50:57 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:57 volumio volumio[6678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:57 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:58 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 16:50:58 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 16:50:58 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 28 16:50:58 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 28 16:50:58 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 28 16:50:58 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 28 16:50:58 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 28 16:50:58 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 28 16:50:58 volumio volumio[6678]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:58 volumio volumio[6678]: info: [1769593858137] CoreMusicLibrary::Adding element Last_100 Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:58 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:58 volumio volumio[6678]: info: [1769593858155] CoreMusicLibrary::Adding element Webradio Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:58 volumio volumio[6678]: info: Initializing BBC Radios Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:50:58 volumio volumio[6678]: info: Creating Spotify config file Jan 28 16:50:58 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:50:58 volumio sudo[6888]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 28 16:50:58 volumio sudo[6888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 28 16:50:58 volumio sudo[6888]: pam_unix(sudo:session): session closed for user root Jan 28 16:50:59 volumio volumio[6809]: Starting albumart workers Jan 28 16:50:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:50:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:50:59 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:50:59 volumio volumio[6810]: Starting albumart workers Jan 28 16:50:59 volumio volumio[6678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:50:59 volumio volumio[6678]: info: [1769593859489] CoreMusicLibrary::Adding element YouTube Music Jan 28 16:50:59 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:50:59 volumio volumio[6678]: Cannot find translation for source YouTube Music Jan 28 16:50:59 volumio volumio[6811]: Starting albumart workers Jan 28 16:50:59 volumio volumio[6678]: info: Volumio Calling Home Jan 28 16:50:59 volumio sudo[6905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Jan 28 16:50:59 volumio sudo[6905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:50:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 28 16:50:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:59 volumio go-librespot[6910]: go-librespot daemon starting... Jan 28 16:50:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:50:59 volumio go-librespot[6911]: time="2026-01-28T16:50:59+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:50:59 volumio sudo[6905]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:00 volumio volumio[6678]: info: Discovery: adding 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 16:51:00 volumio volumio[6678]: info: Discovery: Found device Volumio Jan 28 16:51:00 volumio volumio[6678]: info: CoreCommandRouter::volumioGetState Jan 28 16:51:00 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:51:00 volumio go-librespot[6911]: time="2026-01-28T16:51:00+07:00" level=info msg="zeroconf server listening on port 38929" Jan 28 16:51:00 volumio volumio[6678]: info: Discovery: this is already registered, 921648ed-0557-4d70-9927-1420682efcc7 Jan 28 16:51:00 volumio volumio[6678]: info: Discovery: Found device Volumio Jan 28 16:51:00 volumio volumio[6678]: info: CoreCommandRouter::volumioGetState Jan 28 16:51:00 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:51:00 volumio volumio[6678]: info: MPD Permissions set Jan 28 16:51:00 volumio volumio[6678]: info: MPD Permissions set Jan 28 16:51:00 volumio volumio[6678]: info: Upmpdcli Daemon Started Jan 28 16:51:00 volumio volumio[6678]: info: Volumio called home Jan 28 16:51:00 volumio volumio[6678]: info: Spotify config file written Jan 28 16:51:01 volumio sudo[6920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 28 16:51:01 volumio sudo[6920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:51:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 28 16:51:01 volumio systemd[1]: go-librespot-daemon.service: Killing process 6912 (go-librespot) with signal SIGKILL. Jan 28 16:51:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 28 16:51:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:01 volumio volumio[6678]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 28 16:51:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:01 volumio go-librespot[6922]: go-librespot daemon starting... Jan 28 16:51:01 volumio sudo[6920]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:01 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:01 volumio go-librespot[6923]: time="2026-01-28T16:51:01+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:51:01 volumio go-librespot[6923]: time="2026-01-28T16:51:01+07:00" level=debug msg="app state loaded" Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:51:01 volumio go-librespot[6923]: time="2026-01-28T16:51:01+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 28 16:51:01 volumio volumio[6678]: info: No need to fix Spotify hosts Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=info msg="zeroconf server listening on port 46429" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="obtained new client token: AADVxTA4iK83gVp2sTiEc8xrDqHEsTjyCVcWWhHnoB/jTnYoT3qSdHH4EYi7njeqcE0eKd/JNx0hU0+yyukDW8dtXCSc6SNYifFFMWgRpWVnfS+S5fm9f0gFx6VGn8nKasJQo+pfLPfxaOPt+7xK4xfoBn/YddVM9Cx8L3X8cXtoTFv8JrjBDZs/A6SF56h03jACyS0LknSSLcFz195GeNl4ey9hMvZq+tCuqe3V8tt5bf853UZdcBm0B9I=" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:51:02 volumio volumio[6678]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 16:51:02 volumio volumio[6678]: SPOTIFY: BQC9KCuE824Xfi488KOfqko7oneAGHdmEmWlUCUeBwffTV6_VeNlKaQe2SagDtROSrZUDWccH3vSWzj7ES1bGPxTFUQ2NXzLkC_j-gEVtPBtC9S955PqvWspmxRvkaAIcnk1Dkrx4KUYzrwRogAnJ-GxnOU6eZw6Z-j4dm___I3IYgonZMLWESNXWueIEhwG4SpI98-BcnfHy7xLeFHCza0vmnCvfhY_rydnRuUCbgQ2bKTsZlShpeRuxdFLxfdi8g5O4__A8aOhQZ4DsNMjpvaHopJRWe3KCLoDrI483_UlhMlmdYIA9pv1 Jan 28 16:51:02 volumio volumio[6678]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 28 16:51:02 volumio volumio[6678]: info: New Spotify access token = BQC9KCuE824Xfi488KOfqko7oneAGHdmEmWlUCUeBwffTV6_VeNlKaQe2SagDtROSrZUDWccH3vSWzj7ES1bGPxTFUQ2NXzLkC_j-gEVtPBtC9S955PqvWspmxRvkaAIcnk1Dkrx4KUYzrwRogAnJ-GxnOU6eZw6Z-j4dm___I3IYgonZMLWESNXWueIEhwG4SpI98-BcnfHy7xLeFHCza0vmnCvfhY_rydnRuUCbgQ2bKTsZlShpeRuxdFLxfdi8g5O4__A8aOhQZ4DsNMjpvaHopJRWe3KCLoDrI483_UlhMlmdYIA9pv1 Jan 28 16:51:02 volumio volumio[6678]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 28 16:51:02 volumio volumio[6678]: info: Starting Shairport Sync Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="completed keyexchange" Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16:51:02+07:00" level=debug msg="completed challenge" Jan 28 16:51:02 volumio volumio[6678]: info: Starting Shairport Sync Jan 28 16:51:02 volumio volumio[6678]: info: Starting Shairport Sync Jan 28 16:51:02 volumio go-librespot[6923]: time="2026-01-28T16: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 28 16:51:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:51:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:51:02 volumio sudo[6960]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:51:02 volumio sudo[6960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:51:02 volumio sudo[6962]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:51:02 volumio sudo[6962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:51:02 volumio sudo[6964]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 28 16:51:02 volumio sudo[6964]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:51:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 28 16:51:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 28 16:51:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 16:51:02 volumio systemd[1]: shairport-sync.service: Consumed 2.369s CPU time. Jan 28 16:51:03 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 28 16:51:03 volumio sudo[6960]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:03 volumio sudo[6962]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:03 volumio sudo[6964]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:03 volumio volumio[6678]: info: CoreCommandRouter::volumioGetState Jan 28 16:51:03 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:51:03 volumio volumio[6678]: info: Shairport-Sync Started Jan 28 16:51:03 volumio volumio[6678]: Error adding Membership: Error: addMembership EINVAL Jan 28 16:51:03 volumio volumio[6678]: info: Shairport-Sync Started Jan 28 16:51:03 volumio volumio[6678]: info: Shairport-Sync Started Jan 28 16:51:03 volumio volumio[6678]: SPOTIFY: User informations: {"country":"PK","display_name":"215mmgea6kss3jxeqsqdquvji","email":"linh.ngotran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/215mmgea6kss3jxeqsqdquvji"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/215mmgea6kss3jxeqsqdquvji","id":"215mmgea6kss3jxeqsqdquvji","images":[],"product":"premium","type":"user","uri":"spotify:user:215mmgea6kss3jxeqsqdquvji"} Jan 28 16:51:03 volumio volumio[6678]: info: Spotify Successfully logged in Jan 28 16:51:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:03 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:03 volumio volumio[6678]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 28 16:51:03 volumio volumio[6678]: info: [1769593863442] CoreMusicLibrary::Adding element Spotify Jan 28 16:51:03 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 28 16:51:03 volumio volumio[6678]: Cannot find translation for source YouTube Music Jan 28 16:51:03 volumio volumio[6678]: Cannot find translation for source Spotify Jan 28 16:51:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:05 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:05 volumio volumio[6678]: info: go-librespot daemon successfully initialized Jan 28 16:51:05 volumio mpd[6903]: 2026-01-28T16:51:05 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 28 16:51:05 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 28 16:51:05 volumio sudo[6874]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:05 volumio sudo[6863]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 28 16:51:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:05 volumio go-librespot[7002]: go-librespot daemon starting... Jan 28 16:51:05 volumio go-librespot[7003]: time="2026-01-28T16:51:05+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:51:05 volumio go-librespot[7003]: time="2026-01-28T16:51:05+07:00" level=debug msg="app state loaded" Jan 28 16:51:05 volumio go-librespot[7003]: time="2026-01-28T16:51:05+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:51:05 volumio volumio[6678]: error: MPD error: The expression evaluated to a falsy value: Jan 28 16:51:05 volumio volumio[6678]: assert.ok(self.idling) Jan 28 16:51:05 volumio volumio[6678]: error: The expression evaluated to a falsy value: Jan 28 16:51:05 volumio volumio[6678]: assert.ok(self.idling) Jan 28 16:51:05 volumio volumio[6678]: info: MPD running with PID6903 Jan 28 16:51:05 volumio volumio[6678]: ,establishing connection Jan 28 16:51:05 volumio volumio[6678]: error: updateQueue error: null Jan 28 16:51:05 volumio volumio[6678]: error: updateQueue error: null Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=info msg="zeroconf server listening on port 37089" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="obtained new client token: AACbVF+eF8isTs89LCplAmo3SyYy9qwMV7jsH4n0+PM/ZGLwvRE5TWky60VCb1+DGHBCcmmZNsPvIL/vH9e/LCq55RHMs3rZAJOp0B5dnVj4VvkY2d3qJvqHSVR3EBS19LX1G1JIPcHiLHXwIhwabEaFpdAZcKl8JEEhOsUVlDSuKzLnrdCvspJJHyi4kYz+k1q9o+Q9fMuQauSAbLFG1+q9b+MWkhOHvCbZwO0k9r+imgBMFkZo5DUOK44=" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="completed keyexchange" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16:51:06+07:00" level=debug msg="completed challenge" Jan 28 16:51:06 volumio go-librespot[7003]: time="2026-01-28T16: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 28 16:51:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:51:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:51:07 volumio volumio[6678]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jan 28 16:51:07 volumio volumio[6678]: info: CoreCommandRouter::volumioRetrievevolume Jan 28 16:51:07 volumio volumio[6678]: info: VolumeController:: Volume=100 Mute =false Jan 28 16:51:07 volumio volumio[6678]: info: CoreCommandRouter::volumioGetState Jan 28 16:51:07 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:51:07 volumio volumio[6678]: info: CoreStateMachine::pushState Jan 28 16:51:07 volumio volumio[6678]: info: CorePlayQueue::getTrack 0 Jan 28 16:51:07 volumio volumio[6678]: info: CoreCommandRouter::volumioPushState Jan 28 16:51:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:07 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:07 volumio volumio[6678]: info: Completed starting Core Plugins Jan 28 16:51:07 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:51:07 volumio volumio[6678]: info: ----- MyVolumio plugins startup ---- Jan 28 16:51:07 volumio volumio[6678]: info: ------------------------------------------- Jan 28 16:51:07 volumio volumio[6678]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 28 16:51:08 volumio volumio[6678]: info: Initializing connection to go-librespot Websocket Jan 28 16:51:08 volumio volumio[6678]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 16:51:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:09 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 28 16:51:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:10 volumio go-librespot[7012]: go-librespot daemon starting... Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=debug msg="app state loaded" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16: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-gew1.spotify.com:80]" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16: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 gew1-dealer.spotify.com:443]" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16: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 gew1-spclient.spotify.com:443]" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=info msg="zeroconf server listening on port 34355" Jan 28 16:51:10 volumio volumio[6678]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=debug msg="obtained new client token: AAC+nfKbJpfeN3AoG+sHQQbOb0LXy1J2a7IJ8ttY8nhSz9D1P29vIfpJwKGHcbgyX6p5XHRNkLN0DLAHM9VUyIjU00kZwjRNpmxoiD/9x3hIo0N1hr8mrK2juSjlBKXTS/m0uc/LcdJWXxskPeDWkSqnMw71SMH1i5SUu49rnFqO4k9y+O+yUyUtiaHae+tICR2UwyC3271GW7VYuWWFvnsBc3IVR/e2HMcCoB0C/54DcVQ6i1QHNwq2UT8=" Jan 28 16:51:10 volumio go-librespot[7013]: time="2026-01-28T16:51:10+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:51:11 volumio go-librespot[7013]: time="2026-01-28T16:51:11+07:00" level=debug msg="completed keyexchange" Jan 28 16:51:11 volumio go-librespot[7013]: time="2026-01-28T16:51:11+07:00" level=debug msg="completed challenge" Jan 28 16:51:11 volumio go-librespot[7013]: time="2026-01-28T16: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 28 16:51:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:51:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:51:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:11 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:11 volumio volumio[6678]: info: Initializing connection to go-librespot Websocket Jan 28 16:51:11 volumio volumio[6678]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 16:51:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:13 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 28 16:51:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:14 volumio go-librespot[7020]: go-librespot daemon starting... Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=debug msg="app state loaded" Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:51:14 volumio volumio[6678]: info: Initializing connection to go-librespot Websocket Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=debug msg="new websocket client" Jan 28 16:51:14 volumio volumio[6678]: info: Connection to go-librespot Websocket established Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 28 16:51:14 volumio go-librespot[7021]: time="2026-01-28T16:51:14+07:00" level=info msg="zeroconf server listening on port 43321" Jan 28 16:51:15 volumio go-librespot[7021]: time="2026-01-28T16:51:15+07:00" level=debug msg="obtained new client token: AAC1oPoW2Z8/mes0bgEG5jNvr978NaCBjVdGiVWAy1l0CZiYEU0dnGg7rSypnyGNSGCt9dnSg+YK9wkeMGp2pu7p3yfJdTmZ5W9WIQMBI/tWnOL/TYEvDvqRTIapuEOJjLn+Y7LdxFJZAu++3WbWHU0WU/0mGQ6Sq+0sUXJtjK7X+Yh+SHtvhgrP3oTBV47S+9iTUFquvq57rA18JyfrLYY4ubHkdLP41Sqku2B4RFp/qkTM1YKs6QXi" Jan 28 16:51:15 volumio go-librespot[7021]: time="2026-01-28T16:51:15+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:51:15 volumio go-librespot[7021]: time="2026-01-28T16:51:15+07:00" level=debug msg="completed keyexchange" Jan 28 16:51:15 volumio go-librespot[7021]: time="2026-01-28T16:51:15+07:00" level=debug msg="completed challenge" Jan 28 16:51:15 volumio go-librespot[7021]: time="2026-01-28T16: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 28 16:51:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:15 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:51:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:51:15 volumio volumio[6678]: info: Connection to go-librespot Websocket closed Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin bluetooth to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin multiroom to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin metavolumio to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin cd_controller to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 28 16:51:16 volumio volumio[6678]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 28 16:51:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:17 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:18 volumio volumio[6678]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 28 16:51:18 volumio volumio[6678]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 28 16:51:18 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:51:18 volumio volumio[6678]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 28 16:51:18 volumio volumio[6678]: info: Starting MyVolumio Remote Streaming Endpoints Jan 28 16:51:18 volumio volumio[6678]: info: MyVolumio login type: Token Jan 28 16:51:18 volumio volumio[6678]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 28 16:51:18 volumio volumio[6678]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 28 16:51:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 28 16:51:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 28 16:51:18 volumio go-librespot[7043]: go-librespot daemon starting... Jan 28 16:51:18 volumio go-librespot[7044]: time="2026-01-28T16:51:18+07:00" level=info msg="running go-librespot 0.4.0" Jan 28 16:51:18 volumio go-librespot[7044]: time="2026-01-28T16:51:18+07:00" level=debug msg="app state loaded" Jan 28 16:51:18 volumio go-librespot[7044]: time="2026-01-28T16:51:18+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=info msg="zeroconf server listening on port 33359" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="obtained new client token: AACIBtQfnFR/lfRzrbB4j+39qO3SRxMRyRGP+8YgGvduOa8l0vjmURZhOdFpuBYdL5+323vSMH47ffo+Vfj6T6CJvqNOFm0rRWAjHMrNjPT3NTJkMH8Kktr3SPl/E5/SQjwLVDia8XV/YOuFitAspp13P5+5pNKpWGOzg1xap7BIinPEYN/ZSW7/mT/Di+taMw6UxAdMl6J2+QmjwoJohpcXhCqRQn14bR41cb1go+0QJCzpRPOTO60tI8o=" Jan 28 16:51:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:19 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="completed keyexchange" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16:51:19+07:00" level=debug msg="completed challenge" Jan 28 16:51:19 volumio go-librespot[7044]: time="2026-01-28T16: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 28 16:51:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 28 16:51:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 28 16:51:19 volumio volumio[6678]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 28 16:51:19 volumio volumio[6678]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 28 16:51:19 volumio volumio[6678]: info: Streaming services startup Jan 28 16:51:20 volumio volumio[6678]: info: Starting Streaming Daemon Jan 28 16:51:20 volumio sudo[7052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 28 16:51:20 volumio sudo[7052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 28 16:51:20 volumio volumio[6678]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 28 16:51:20 volumio sudo[7052]: pam_unix(sudo:session): session closed for user root Jan 28 16:51:20 volumio volumio[6678]: info: Getting Spotify volume Jan 28 16:51:20 volumio volumio[6678]: info: Initializing connection to go-librespot Websocket Jan 28 16:51:20 volumio volumio[6678]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 16:51:20 volumio volumio[6678]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 28 16:51:20 volumio volumio[6678]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 28 16:51:20 volumio volumio[6678]: errno: -111, Jan 28 16:51:20 volumio volumio[6678]: code: 'ECONNREFUSED', Jan 28 16:51:20 volumio volumio[6678]: syscall: 'connect', Jan 28 16:51:20 volumio volumio[6678]: address: '127.0.0.1', Jan 28 16:51:20 volumio volumio[6678]: port: 9879, Jan 28 16:51:20 volumio volumio[6678]: response: undefined Jan 28 16:51:20 volumio volumio[6678]: } Jan 28 16:51:20 volumio volumio[6678]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 28 16:51:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Failed to resolve host name Jan 28 16:51:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:389::MPDCli::updStatus: no connection Jan 28 16:51:21 volumio upmpdcli[1383]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Jan 28 16:51:21 volumio sudo[7072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-28 16:50' Jan 28 16:51:21 volumio sudo[7072]: 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"