Mar 24 10:31:00 volumio go-librespot[24999]: time="2026-03-24T10:31:00Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.65.9:80: connect: connection refused" Mar 24 10:31:00 volumio go-librespot[24999]: time="2026-03-24T10:31:00Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:31:00 volumio go-librespot[24999]: time="2026-03-24T10:31:00Z" level=debug msg="completed keyexchange" Mar 24 10:31:00 volumio go-librespot[24999]: time="2026-03-24T10:31:00Z" level=debug msg="completed challenge" Mar 24 10:31:00 volumio go-librespot[24999]: time="2026-03-24T10:31:00Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:00 volumio volumio[24783]: info: go-librespot daemon successfully initialized Mar 24 10:31:01 volumio go-librespot[24999]: time="2026-03-24T10:31:01Z" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 10:31:01 volumio go-librespot[24999]: time="2026-03-24T10:31:01Z" level=debug msg="completed keyexchange" Mar 24 10:31:01 volumio go-librespot[24999]: time="2026-03-24T10:31:01Z" level=debug msg="completed challenge" Mar 24 10:31:01 volumio go-librespot[24999]: time="2026-03-24T10:31:01Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:02 volumio go-librespot[24999]: time="2026-03-24T10:31:02Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:02 volumio go-librespot[24999]: time="2026-03-24T10:31:02Z" level=debug msg="completed keyexchange" Mar 24 10:31:02 volumio go-librespot[24999]: time="2026-03-24T10:31:02Z" level=debug msg="completed challenge" Mar 24 10:31:02 volumio go-librespot[24999]: time="2026-03-24T10:31:02Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:03 volumio go-librespot[24999]: time="2026-03-24T10:31:03Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:03 volumio go-librespot[24999]: time="2026-03-24T10:31:03Z" level=debug msg="completed keyexchange" Mar 24 10:31:03 volumio go-librespot[24999]: time="2026-03-24T10:31:03Z" level=debug msg="completed challenge" Mar 24 10:31:03 volumio go-librespot[24999]: time="2026-03-24T10:31:03Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:03 volumio go-librespot[24999]: time="2026-03-24T10:31:03Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:03 volumio volumio[24783]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:03 volumio volumio[24783]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:05 volumio sudo[25052]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:05 volumio sudo[25052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:05 volumio sudo[25054]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:05 volumio sudo[25054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:05 volumio sudo[25052]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:05 volumio sudo[25054]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:05 volumio sudo[25056]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 10:31:05 volumio sudo[25056]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:05 volumio sudo[25056]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:05 volumio volumio[24783]: info: Upmpdcli Daemon Started Mar 24 10:31:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 10:31:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:06 volumio go-librespot[25060]: go-librespot daemon starting... Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="app state loaded" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=info msg="zeroconf server listening on port 33277" Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin bluetooth to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin multiroom to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin metavolumio to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin cd_controller to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="obtained new client token: AACDx+McnNzBbw4YLj3dIEL1Hy1wCJ4/DwM8NCQ1YG57mxClprfFSzqfnRjSjcLvKamMAoDRTbFQjTPb6mu7mBjFxUw7VrZbKDVWHnhWXVsN+cj127cv5/5G4IN+2myCuNz69KcHolfuK+IQbNCZ2EMUHQmBLONRFDliEPg6BeI6B8+JOdRvMYcfOrodL+tlW0ttrRvjlgPg4mXuU6oL+u996jIIBCqwMm0UmvpUt/eSIiOxiQyfGZ7UEQ==" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="completed keyexchange" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=debug msg="completed challenge" Mar 24 10:31:06 volumio go-librespot[25061]: time="2026-03-24T10:31:06Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 24 10:31:06 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:06 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:06 volumio volumio[24783]: info: Starting MyVolumio Remote Streaming Endpoints Mar 24 10:31:06 volumio volumio[24783]: info: MyVolumio login type: Token Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 24 10:31:06 volumio volumio[24783]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 24 10:31:07 volumio volumio[24783]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 24 10:31:07 volumio volumio[24783]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 24 10:31:07 volumio volumio[24783]: info: Streaming services startup Mar 24 10:31:07 volumio volumio[24783]: info: Starting Streaming Daemon Mar 24 10:31:07 volumio sudo[25071]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:07 volumio sudo[25071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:07 volumio volumio[24783]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 24 10:31:07 volumio sudo[25071]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:07 volumio volumio[24783]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:07 volumio volumio[24783]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:07 volumio volumio[24783]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:07 volumio volumio[24783]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="new websocket client" Mar 24 10:31:07 volumio volumio[24783]: info: Connection to go-librespot Websocket established Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="completed keyexchange" Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="completed challenge" Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:07 volumio volumio[24783]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:07 volumio volumio[24783]: info: MyVolumio token set successfully Mar 24 10:31:07 volumio volumio[24783]: info: MYVOLUMIO: Adding device Mar 24 10:31:07 volumio volumio[24783]: info: MYVOLUMIO: Evaluating Server Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="completed keyexchange" Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=debug msg="completed challenge" Mar 24 10:31:07 volumio go-librespot[25061]: time="2026-03-24T10:31:07Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:08 volumio volumio[24783]: info: MyVolumio status changed Mar 24 10:31:08 volumio volumio[24783]: info: Streaming services startup Mar 24 10:31:08 volumio volumio[24783]: info: Starting Streaming Daemon Mar 24 10:31:08 volumio volumio[24783]: info: Removing browser output: myVolumio user plan is not superstar Mar 24 10:31:08 volumio volumio[24783]: info: Removing audio output: Mar 24 10:31:08 volumio volumio[24783]: info: Stoppping Tunnel 1 Mar 24 10:31:08 volumio sudo[25098]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:08 volumio sudo[25098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:08 volumio sudo[25100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 24 10:31:08 volumio sudo[25100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio sudo[25098]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:08 volumio volumio[24783]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:08 volumio volumio[24783]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:08 volumio volumio[24783]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:08 volumio sudo[25100]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:08 volumio volumio[24783]: info: Remote SSH Stopped Mar 24 10:31:08 volumio volumio[24783]: info: Setting Geolocation for MyVolumio to eu3 Mar 24 10:31:08 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:08 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:08 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:08 volumio go-librespot[25061]: time="2026-03-24T10:31:08Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:31:08 volumio volumio[24783]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 24 10:31:08 volumio go-librespot[25061]: time="2026-03-24T10:31:08Z" level=debug msg="completed keyexchange" Mar 24 10:31:08 volumio go-librespot[25061]: time="2026-03-24T10:31:08Z" level=debug msg="completed challenge" Mar 24 10:31:08 volumio go-librespot[25061]: time="2026-03-24T10:31:08Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:09 volumio go-librespot[25061]: time="2026-03-24T10:31:09Z" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 10:31:09 volumio volumio[24783]: info: Updating MyVolumio device info Mar 24 10:31:09 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:09 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:09 volumio volumio[24783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:09 volumio go-librespot[25061]: time="2026-03-24T10:31:09Z" level=debug msg="completed keyexchange" Mar 24 10:31:09 volumio go-librespot[25061]: time="2026-03-24T10:31:09Z" level=debug msg="completed challenge" Mar 24 10:31:09 volumio go-librespot[25061]: time="2026-03-24T10:31:09Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:09 volumio volumio[24783]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Mar 24 10:31:10 volumio go-librespot[25061]: time="2026-03-24T10:31:10Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:10 volumio volumio[24783]: info: Getting Spotify volume Mar 24 10:31:10 volumio volumio[24783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 24 10:31:10 volumio volumio[24783]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:10 volumio volumio[24783]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:10 volumio volumio[24783]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Mar 24 10:31:10 volumio volumio[24783]: SPOTIFY: SPOTIFY VOLUME undefined Mar 24 10:31:10 volumio volumio[24783]: SPOTIFY: VOLUMIO VOLUME 0 Mar 24 10:31:10 volumio volumio[24783]: info: Aligning Spotify Volume to Volumio Volume Mar 24 10:31:10 volumio volumio[24783]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:10 volumio volumio[24783]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:10 volumio volumio[24783]: info: Setting Spotify Volume from Volumio: 0 Mar 24 10:31:10 volumio go-librespot[25061]: time="2026-03-24T10:31:10Z" level=debug msg="completed keyexchange" Mar 24 10:31:10 volumio go-librespot[25061]: time="2026-03-24T10:31:10Z" level=debug msg="completed challenge" Mar 24 10:31:10 volumio go-librespot[25061]: time="2026-03-24T10:31:10Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:10 volumio go-librespot[25061]: time="2026-03-24T10:31:10Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:10 volumio volumio[24783]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:10 volumio volumio[24783]: Error: socket hang up Mar 24 10:31:10 volumio volumio[24783]: at connResetException (node:internal/errors:720:14) Mar 24 10:31:10 volumio volumio[24783]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 24 10:31:10 volumio volumio[24783]: at Socket.emit (node:events:526:35) Mar 24 10:31:10 volumio volumio[24783]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 24 10:31:10 volumio volumio[24783]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 24 10:31:10 volumio volumio[24783]: code: 'ECONNRESET', Mar 24 10:31:10 volumio volumio[24783]: response: undefined Mar 24 10:31:10 volumio volumio[24783]: } Mar 24 10:31:10 volumio volumio[24783]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:10 volumio sudo[25118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 10:30' Mar 24 10:31:10 volumio sudo[25118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:10 volumio sudo[25118]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:10 volumio volumio-remote-updater[945]: [2026-03-24 10:31:10] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 10:31:10 volumio volumio-remote-updater[945]: [2026-03-24 10:31:10] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 10:31:10 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:10 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 10:31:10 volumio systemd[1]: volumio.service: Consumed 8.957s CPU time. Mar 24 10:31:10 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:10 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:11 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 78079. Mar 24 10:31:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:11 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 10:31:11 volumio systemd[1]: volumio.service: Consumed 8.957s CPU time. Mar 24 10:31:11 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 10:31:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:11 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:11 volumio volumio[25134]: info: ----- Volumio3 ---- Mar 24 10:31:11 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:11 volumio volumio[25134]: info: ----- System startup ---- Mar 24 10:31:11 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:11 volumio volumio[25134]: info: MYVOLUMIO Environment detected Mar 24 10:31:11 volumio volumio[25134]: info: Plugin folders cleanup Mar 24 10:31:11 volumio volumio[25134]: info: Scanning into folder /volumio/app/plugins/ Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category audio_interface Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category miscellanea Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category music_service Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category plugins.json Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category system_controller Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category user_interface Mar 24 10:31:11 volumio volumio[25134]: info: Scanning into folder /data/plugins/ Mar 24 10:31:11 volumio volumio[25134]: info: Scanning category music_service Mar 24 10:31:11 volumio volumio[25134]: info: Plugin folders cleanup completed Mar 24 10:31:11 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:11 volumio volumio[25134]: info: ----- Core plugins startup ---- Mar 24 10:31:11 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:11 volumio volumio[25134]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 10:31:11 volumio volumio[25134]: info: Adding plugin upnp to MyMusic Plugins Mar 24 10:31:11 volumio volumio[25134]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 10:31:11 volumio volumio[25134]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 10:31:11 volumio volumio[25134]: info: Loading plugins from folder /data/plugins/ Mar 24 10:31:11 volumio volumio[25134]: info: Adding plugin rtlsdr_radio to MyMusic Plugins Mar 24 10:31:11 volumio volumio[25134]: info: Loading plugin "system"... Mar 24 10:31:11 volumio volumio[25134]: info: Loading plugin "appearance"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "network"... Mar 24 10:31:12 volumio volumio[25134]: info: Refreshing Cached IP Addresses Mar 24 10:31:12 volumio sudo[25162]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:12 volumio sudo[25162]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:12 volumio sudo[25164]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:12 volumio sudo[25164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:12 volumio sudo[25162]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:12 volumio sudo[25164]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "services"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "alsa_controller"... Mar 24 10:31:12 volumio sudo[25177]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 10:31:12 volumio sudo[25177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:12 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "wizard"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "networkfs"... Mar 24 10:31:12 volumio volumio[25134]: info: Starting Udev Watcher for removable devices Mar 24 10:31:12 volumio volumio[25134]: info: Mounting Device 0ACB-A1DE Mar 24 10:31:12 volumio sudo[25201]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/0ACB-A1DE -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:12 volumio sudo[25201]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:12 volumio sudo[25201]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:12 volumio volumio[25134]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:12 volumio volumio[25134]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:12 volumio volumio[25134]: error: Failed to mount 0ACB-A1DE: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/0ACB-A1DE" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:12 volumio volumio[25134]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:12 volumio volumio[25134]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:12 volumio volumio[25134]: info: Ignoring mount for partition: boot Mar 24 10:31:12 volumio volumio[25134]: info: Ignoring mount for partition: volumio Mar 24 10:31:12 volumio volumio[25134]: info: Ignoring mount for partition: volumio_data Mar 24 10:31:12 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "volumio_command_line_client"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "upnp"... Mar 24 10:31:12 volumio volumio[25134]: info: [1774348272377] Starting Upmpd Daemon Mar 24 10:31:12 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "my_music"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "mpd"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "upnp_browser"... Mar 24 10:31:12 volumio volumio[25134]: info: Starting UPNP Browser Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "alarm-clock"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "airplay_emulation"... Mar 24 10:31:12 volumio volumio[25134]: info: Starting Shairport Sync Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "last_100"... Mar 24 10:31:12 volumio volumio[25134]: info: Loading plugin "webradio"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "i2s_dacs"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "volumiodiscovery"... Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** For more information see Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:13 volumio volumio[25134]: *** WARNING *** For more information see Mar 24 10:31:13 volumio node[25134]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:13 volumio node[25134]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:13 volumio node[25134]: *** WARNING *** For more information see Mar 24 10:31:13 volumio node[25134]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:13 volumio node[25134]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:13 volumio node[25134]: *** WARNING *** For more information see Mar 24 10:31:13 volumio volumio[25134]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 10:31:13 volumio volumio[25134]: info: Discovery: Started advertising with name: Volumio Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "spop"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "ytmusic"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "outputs"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "albumart"... Mar 24 10:31:13 volumio volumio[25134]: info: Plugin example_plugin is not enabled Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "inputs"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "updater_comm"... Mar 24 10:31:13 volumio volumio[25134]: info: Plugin mpdemulation is not enabled Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "rest_api"... Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "websocket"... Mar 24 10:31:13 volumio volumio[25134]: info: Starting Socket.io Server version 1.7.4 Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "podcast"... Mar 24 10:31:13 volumio volumio[25134]: info: ControllerPodcast::constructor Mar 24 10:31:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 24 10:31:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:13 volumio volumio[25134]: info: Loading plugin "rtlsdr_radio"... Mar 24 10:31:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:13 volumio go-librespot[25215]: go-librespot daemon starting... Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=debug msg="app state loaded" Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:13 volumio volumio[25205]: Forking 3 albumart workers Mar 24 10:31:13 volumio volumio[25134]: info: Loading i18n strings for locale en Mar 24 10:31:13 volumio volumio[25134]: Updating browse sources language Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::initPlayerControls Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: Express server listening on port 3000 Mar 24 10:31:13 volumio volumio[25134]: [Metrics] WebUI: 2s 321.85ms Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::resetVolumioState Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::getcurrentVolume Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:13 volumio go-librespot[25216]: time="2026-03-24T10:31:13Z" level=info msg="zeroconf server listening on port 42057" Mar 24 10:31:13 volumio volumio[25134]: info: Volumio Network Manager: Network status updated: 2 Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:13 volumio volumio[25134]: info: Reloading queue from file Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::setRepeat null single undefined Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::pushState Mar 24 10:31:13 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::setRandom true Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::pushState Mar 24 10:31:13 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:13 volumio volumio[25134]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 10:31:13 volumio volumio[25134]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Mar 24 10:31:13 volumio volumio[25134]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 10:31:13 volumio volumio[25134]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::pushState Mar 24 10:31:13 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:13 volumio volumio[25134]: info: CoreStateMachine::updateTrackBlock Mar 24 10:31:13 volumio volumio[25134]: info: CorePlayQueue::getTrackBlock Mar 24 10:31:13 volumio volumio[25134]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:14 volumio volumio[25134]: info: Setting Device type: Raspberry PI Mar 24 10:31:14 volumio volumio[25134]: info: Completed loading Core Plugins Mar 24 10:31:14 volumio volumio[25134]: info: Preparing to generate the ALSA configuration file Mar 24 10:31:14 volumio volumio[25134]: info: Asound.conf file unchanged, so no further update is needed Mar 24 10:31:14 volumio volumio[25134]: info: Output device has changed, restarting MPD Mar 24 10:31:14 volumio volumio[25134]: info: Output device has changed, restarting Shairport Sync Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio sudo[25272]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:14 volumio sudo[25272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio sudo[25274]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:14 volumio sudo[25274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio sudo[25272]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio volumio[25134]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:14 volumio volumio[25134]: info: ___________ START PLUGINS ___________ Mar 24 10:31:14 volumio volumio[25134]: info: ControllerMpd::onStart: Initializing MPD Mar 24 10:31:14 volumio volumio[25134]: info: Creating MPD Configuration file Mar 24 10:31:14 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274102] CoreMusicLibrary::Adding element Media Servers Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio sudo[25282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:14 volumio sudo[25282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio volumio[25134]: info: UPNP Browser: Client initialized successfully Mar 24 10:31:14 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:14 volumio sudo[25282]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:14 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:14 volumio sudo[25284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:14 volumio sudo[25284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:14 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:14 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:14 volumio volumio[25134]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274172] CoreMusicLibrary::Adding element Last_100 Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274174] CoreMusicLibrary::Adding element Webradio Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:14 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:14 volumio volumio[25134]: info: Initializing BBC Radios Mar 24 10:31:14 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:14 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:14 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:14 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:14 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:14 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: Creating Spotify config file Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25225]: Starting albumart workers Mar 24 10:31:14 volumio volumio[25224]: Starting albumart workers Mar 24 10:31:14 volumio volumio[25223]: Starting albumart workers Mar 24 10:31:14 volumio sudo[25300]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 10:31:14 volumio sudo[25300]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 10:31:14 volumio sudo[25300]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio go-librespot[25216]: time="2026-03-24T10:31:14Z" level=debug msg="obtained new client token: AABK3X5Ohl6N6oC2PVZpIkLH9PxxY99i6QEjrzXQy6KwILDDl2gVGSK5V2LXhVLGTQiiEzwOetJSptX9gGTFy5D1hfxlMTh7jeXK7p8TSHesPtDciauzv6gyd4jInPvVU9O1SNDP9qRbGIS1b9oKl5R9ZF7Im12dDZZzzgDl8/W7W8DCyyFFquct6LIQzv0ba804Wl8p9reva57PeABVO/up06rrNgj2lah9HrBM6aJd1HjS/IRXhrHjyw==" Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274438] CoreMusicLibrary::Adding element YouTube Music Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source YouTube Music Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274449] CoreMusicLibrary::Adding element Podcast Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source YouTube Music Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source Podcast Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Starting plugin Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Loaded i18n strings for language: en Mar 24 10:31:14 volumio volumio[25134]: info: Volumio Calling Home Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] snd-aloop already loaded Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] No stations database found, creating v2 Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Database loaded at: 2026-03-24T10:31:14.520Z Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Loading blocklist from: /data/plugins/music_service/rtlsdr_radio/blocklist.json Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Got 21 phrases from file Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Updated metadata blocklist Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Metadata module now has 21 phrases Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Management server started on port 3456 Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:14 volumio volumio[25134]: info: [1774348274557] CoreMusicLibrary::Adding element FM/DAB Radio Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source YouTube Music Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source Podcast Mar 24 10:31:14 volumio volumio[25134]: Cannot find translation for source FM/DAB Radio Mar 24 10:31:14 volumio volumio[25134]: info: [RTL-SDR Radio] Plugin started successfully Mar 24 10:31:14 volumio volumio[25134]: info: Discovery: adding 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:14 volumio volumio[25134]: info: Discovery: Found device Volumio Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:14 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:14 volumio volumio[25134]: info: Discovery: this is already registered, 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:14 volumio volumio[25134]: info: Discovery: Found device Volumio Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:14 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:14 volumio go-librespot[25216]: time="2026-03-24T10:31:14Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:14 volumio volumio[25134]: info: MPD Permissions set Mar 24 10:31:14 volumio volumio[25134]: info: MPD Permissions set Mar 24 10:31:14 volumio volumio[25134]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:14 volumio volumio[25134]: info: CoreStateMachine::pushState Mar 24 10:31:14 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:14 volumio volumio[25134]: info: Spotify config file written Mar 24 10:31:14 volumio go-librespot[25216]: time="2026-03-24T10:31:14Z" level=debug msg="completed keyexchange" Mar 24 10:31:14 volumio go-librespot[25216]: time="2026-03-24T10:31:14Z" level=debug msg="completed challenge" Mar 24 10:31:14 volumio volumio[25134]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 24 10:31:14 volumio sudo[25340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 10:31:14 volumio sudo[25340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 10:31:14 volumio systemd[1]: go-librespot-daemon.service: Killing process 25217 (go-librespot) with signal SIGKILL. Mar 24 10:31:14 volumio systemd[1]: go-librespot-daemon.service: Killing process 25218 (go-librespot) with signal SIGKILL. Mar 24 10:31:14 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 10:31:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:14 volumio volumio[25134]: info: No need to fix Spotify hosts Mar 24 10:31:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:14 volumio sudo[25340]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio go-librespot[25352]: go-librespot daemon starting... Mar 24 10:31:14 volumio go-librespot[25353]: time="2026-03-24T10:31:14Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:14 volumio go-librespot[25353]: time="2026-03-24T10:31:14Z" level=debug msg="app state loaded" Mar 24 10:31:14 volumio go-librespot[25353]: time="2026-03-24T10:31:14Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:14 volumio volumio[25134]: info: Starting Shairport Sync Mar 24 10:31:14 volumio volumio[25134]: info: Starting Shairport Sync Mar 24 10:31:14 volumio volumio[25134]: info: Starting Shairport Sync Mar 24 10:31:14 volumio sudo[25360]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:14 volumio sudo[25360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio sudo[25365]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:14 volumio sudo[25365]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio sudo[25363]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:14 volumio sudo[25363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:14 volumio volumio[25134]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:14 volumio volumio[25134]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:14 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 10:31:14 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 10:31:14 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:14 volumio systemd[1]: shairport-sync.service: Consumed 1.544s CPU time. Mar 24 10:31:14 volumio volumio[25134]: info: Volumio called home Mar 24 10:31:14 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:14 volumio sudo[25363]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio sudo[25360]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio sudo[25365]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:14 volumio volumio[25134]: info: Shairport-Sync Started Mar 24 10:31:14 volumio volumio[25134]: Error adding Membership: Error: addMembership EINVAL Mar 24 10:31:14 volumio volumio[25134]: info: Shairport-Sync Started Mar 24 10:31:14 volumio volumio[25134]: info: Shairport-Sync Started Mar 24 10:31:14 volumio mpd[25313]: 2026-03-24T10:31:14 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 10:31:15 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 10:31:15 volumio sudo[25284]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:15 volumio sudo[25274]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:15 volumio volumio[25134]: info: Completed starting Core Plugins Mar 24 10:31:15 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:15 volumio volumio[25134]: info: ----- MyVolumio plugins startup ---- Mar 24 10:31:15 volumio volumio[25134]: info: ------------------------------------------- Mar 24 10:31:15 volumio volumio[25134]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 24 10:31:15 volumio volumio[25134]: error: MPD error: The expression evaluated to a falsy value: Mar 24 10:31:15 volumio volumio[25134]: assert.ok(self.idling) Mar 24 10:31:15 volumio volumio[25134]: error: The expression evaluated to a falsy value: Mar 24 10:31:15 volumio volumio[25134]: assert.ok(self.idling) Mar 24 10:31:15 volumio volumio[25134]: info: MPD running with PID25313 Mar 24 10:31:15 volumio volumio[25134]: ,establishing connection Mar 24 10:31:15 volumio volumio[25134]: error: updateQueue error: null Mar 24 10:31:15 volumio volumio[25134]: error: updateQueue error: null Mar 24 10:31:15 volumio volumio[25134]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=info msg="zeroconf server listening on port 34977" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=debug msg="obtained new client token: AADFZIG/JV+x451PDXR6oU0O5u8vhvgAN9W8qN+CJJBxPWEWZixJscQ1W42fgmrAOg68ZX+6ju0L7+mXziLaPqWc4BeU5l00dHzQXVBNLNjoCHkLQBEs1ELrVHrx4rHuobF9HcYI9f8Q1xqigd6X9I4H4r8qrWZQIffDoY/EP0RvIL4T0GTPbsdgc98KDa/PcsbRrJ08DhEdlLsh7TtkRqBildZ0CVnXT2xBoeWUqV/9qakjTRdzwWOf6g==" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Mar 24 10:31:15 volumio go-librespot[25353]: time="2026-03-24T10:31:15Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:15 volumio volumio-remote-updater[945]: [2026-03-24 10:31:15] [connect] Successful connection Mar 24 10:31:15 volumio volumio-remote-updater[945]: [2026-03-24 10:31:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774348275 101 Mar 24 10:31:15 volumio volumio[25134]: 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: 2 Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=debug msg="completed keyexchange" Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=debug msg="completed challenge" Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:16 volumio sudo[25177]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=debug msg="completed keyexchange" Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=debug msg="completed challenge" Mar 24 10:31:16 volumio go-librespot[25353]: time="2026-03-24T10:31:16Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:17 volumio go-librespot[25353]: time="2026-03-24T10:31:17Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:31:17 volumio go-librespot[25353]: time="2026-03-24T10:31:17Z" level=debug msg="completed keyexchange" Mar 24 10:31:17 volumio go-librespot[25353]: time="2026-03-24T10:31:17Z" level=debug msg="completed challenge" Mar 24 10:31:17 volumio go-librespot[25353]: time="2026-03-24T10:31:17Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:17 volumio volumio[25134]: info: go-librespot daemon successfully initialized Mar 24 10:31:18 volumio go-librespot[25353]: time="2026-03-24T10:31:18Z" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 10:31:18 volumio go-librespot[25353]: time="2026-03-24T10:31:18Z" level=debug msg="completed keyexchange" Mar 24 10:31:18 volumio go-librespot[25353]: time="2026-03-24T10:31:18Z" level=debug msg="completed challenge" Mar 24 10:31:18 volumio go-librespot[25353]: time="2026-03-24T10:31:18Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:18 volumio go-librespot[25353]: time="2026-03-24T10:31:18Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=debug msg="completed keyexchange" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=debug msg="completed challenge" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=debug msg="completed keyexchange" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=debug msg="completed challenge" Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:19 volumio go-librespot[25353]: time="2026-03-24T10:31:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:20 volumio volumio[25134]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:20 volumio volumio[25134]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:22 volumio sudo[25406]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:22 volumio sudo[25406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:22 volumio sudo[25406]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:22 volumio sudo[25408]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:22 volumio sudo[25408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:22 volumio sudo[25408]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:22 volumio sudo[25412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 10:31:22 volumio sudo[25412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:22 volumio sudo[25412]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:22 volumio volumio[25134]: info: Upmpdcli Daemon Started Mar 24 10:31:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 10:31:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:22 volumio go-librespot[25414]: go-librespot daemon starting... Mar 24 10:31:22 volumio go-librespot[25415]: time="2026-03-24T10:31:22Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:22 volumio go-librespot[25415]: time="2026-03-24T10:31:22Z" level=debug msg="app state loaded" Mar 24 10:31:22 volumio go-librespot[25415]: time="2026-03-24T10:31:22Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=info msg="zeroconf server listening on port 43915" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="obtained new client token: AABfuDF1xIuvU9BSfzyWqu28455LbCsniVdoszBkkNVaYw1aGEg1Gblq8yF2jeepYWjJk4S70A6XlgsgbZSd8NHpr/Qfw9u8QYwiGRHnjs+R16xO7Sfm/R0gyWLEFebBZAgqzYHVhEI09vbz7cuQ/mbKgmL+gFp4A1X9Gozl7tmR+s7ob/P3r9xiX2hMyNK/KGrGN1DYtgYO4XaOCL/N2mtbYwlWj3wZX9oYINECIsMrbVPX6mo1lmY=" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="completed keyexchange" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="completed challenge" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin bluetooth to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin multiroom to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin metavolumio to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin cd_controller to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 24 10:31:23 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:23 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:23 volumio volumio[25134]: info: Starting MyVolumio Remote Streaming Endpoints Mar 24 10:31:23 volumio volumio[25134]: info: MyVolumio login type: Token Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="completed keyexchange" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="completed challenge" Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 24 10:31:23 volumio volumio[25134]: info: Streaming services startup Mar 24 10:31:23 volumio volumio[25134]: info: Starting Streaming Daemon Mar 24 10:31:23 volumio sudo[25425]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:23 volumio sudo[25425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:23 volumio volumio[25134]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 24 10:31:23 volumio sudo[25425]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:23 volumio volumio[25134]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:23 volumio volumio[25134]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:23 volumio volumio[25134]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:23 volumio volumio[25134]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:23 volumio volumio[25134]: info: Connection to go-librespot Websocket established Mar 24 10:31:23 volumio go-librespot[25415]: time="2026-03-24T10:31:23Z" level=debug msg="new websocket client" Mar 24 10:31:24 volumio go-librespot[25415]: time="2026-03-24T10:31:24Z" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Mar 24 10:31:24 volumio go-librespot[25415]: time="2026-03-24T10:31:24Z" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 10:31:24 volumio go-librespot[25415]: time="2026-03-24T10:31:24Z" level=debug msg="completed keyexchange" Mar 24 10:31:24 volumio go-librespot[25415]: time="2026-03-24T10:31:24Z" level=debug msg="completed challenge" Mar 24 10:31:24 volumio go-librespot[25415]: time="2026-03-24T10:31:24Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:25 volumio volumio[25134]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 24 10:31:25 volumio go-librespot[25415]: time="2026-03-24T10:31:25Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:25 volumio volumio[25134]: info: MyVolumio token set successfully Mar 24 10:31:25 volumio volumio[25134]: info: MYVOLUMIO: Adding device Mar 24 10:31:25 volumio volumio[25134]: info: MYVOLUMIO: Evaluating Server Mar 24 10:31:25 volumio go-librespot[25415]: time="2026-03-24T10:31:25Z" level=debug msg="completed keyexchange" Mar 24 10:31:25 volumio go-librespot[25415]: time="2026-03-24T10:31:25Z" level=debug msg="completed challenge" Mar 24 10:31:25 volumio volumio[25134]: info: MyVolumio status changed Mar 24 10:31:25 volumio volumio[25134]: info: Streaming services startup Mar 24 10:31:25 volumio volumio[25134]: info: Starting Streaming Daemon Mar 24 10:31:25 volumio volumio[25134]: info: Removing browser output: myVolumio user plan is not superstar Mar 24 10:31:25 volumio volumio[25134]: info: Removing audio output: Mar 24 10:31:25 volumio volumio[25134]: info: Stoppping Tunnel 1 Mar 24 10:31:25 volumio sudo[25452]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:25 volumio sudo[25452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:25 volumio sudo[25454]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 24 10:31:25 volumio sudo[25454]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio sudo[25452]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:25 volumio volumio[25134]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:25 volumio volumio[25134]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:25 volumio volumio[25134]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:25 volumio sudo[25454]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:25 volumio volumio[25134]: info: Remote SSH Stopped Mar 24 10:31:25 volumio go-librespot[25415]: time="2026-03-24T10:31:25Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:25 volumio volumio[25134]: info: Setting Geolocation for MyVolumio to eu3 Mar 24 10:31:25 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:25 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:25 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="completed keyexchange" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="completed challenge" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:26 volumio volumio[25134]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 24 10:31:26 volumio volumio[25134]: info: Updating MyVolumio device info Mar 24 10:31:26 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:26 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:26 volumio volumio[25134]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="completed keyexchange" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=debug msg="completed challenge" Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:26 volumio go-librespot[25415]: time="2026-03-24T10:31:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:26 volumio volumio[25134]: info: Connection to go-librespot Websocket closed Mar 24 10:31:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:26 volumio volumio[25134]: info: Getting Spotify volume Mar 24 10:31:26 volumio volumio[25134]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:26 volumio volumio[25134]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:26 volumio volumio[25134]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 24 10:31:26 volumio volumio[25134]: errno: -111, Mar 24 10:31:26 volumio volumio[25134]: code: 'ECONNREFUSED', Mar 24 10:31:26 volumio volumio[25134]: syscall: 'connect', Mar 24 10:31:26 volumio volumio[25134]: address: '127.0.0.1', Mar 24 10:31:26 volumio volumio[25134]: port: 9879, Mar 24 10:31:26 volumio volumio[25134]: response: undefined Mar 24 10:31:26 volumio volumio[25134]: } Mar 24 10:31:26 volumio volumio[25134]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:27 volumio sudo[25471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 10:30' Mar 24 10:31:27 volumio sudo[25471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:27 volumio sudo[25471]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:27 volumio volumio-remote-updater[945]: [2026-03-24 10:31:27] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 10:31:27 volumio volumio-remote-updater[945]: [2026-03-24 10:31:27] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 10:31:27 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:27 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 10:31:27 volumio systemd[1]: volumio.service: Consumed 8.954s CPU time. Mar 24 10:31:27 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:27 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:27 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 78080. Mar 24 10:31:27 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:27 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 10:31:27 volumio systemd[1]: volumio.service: Consumed 8.954s CPU time. Mar 24 10:31:27 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 10:31:27 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:28 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:28 volumio volumio[25486]: info: ----- Volumio3 ---- Mar 24 10:31:28 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:28 volumio volumio[25486]: info: ----- System startup ---- Mar 24 10:31:28 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:28 volumio volumio[25486]: info: MYVOLUMIO Environment detected Mar 24 10:31:28 volumio volumio[25486]: info: Plugin folders cleanup Mar 24 10:31:28 volumio volumio[25486]: info: Scanning into folder /volumio/app/plugins/ Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category audio_interface Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category miscellanea Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category music_service Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category plugins.json Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category system_controller Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category user_interface Mar 24 10:31:28 volumio volumio[25486]: info: Scanning into folder /data/plugins/ Mar 24 10:31:28 volumio volumio[25486]: info: Scanning category music_service Mar 24 10:31:28 volumio volumio[25486]: info: Plugin folders cleanup completed Mar 24 10:31:28 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:28 volumio volumio[25486]: info: ----- Core plugins startup ---- Mar 24 10:31:28 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:28 volumio volumio[25486]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 10:31:28 volumio volumio[25486]: info: Adding plugin upnp to MyMusic Plugins Mar 24 10:31:28 volumio volumio[25486]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 10:31:28 volumio volumio[25486]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 10:31:28 volumio volumio[25486]: info: Loading plugins from folder /data/plugins/ Mar 24 10:31:28 volumio volumio[25486]: info: Adding plugin rtlsdr_radio to MyMusic Plugins Mar 24 10:31:28 volumio volumio[25486]: info: Loading plugin "system"... Mar 24 10:31:28 volumio volumio[25486]: info: Loading plugin "appearance"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "network"... Mar 24 10:31:29 volumio volumio[25486]: info: Refreshing Cached IP Addresses Mar 24 10:31:29 volumio sudo[25515]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:29 volumio sudo[25515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:29 volumio sudo[25517]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:29 volumio sudo[25517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:29 volumio sudo[25515]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:29 volumio sudo[25517]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "services"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "alsa_controller"... Mar 24 10:31:29 volumio sudo[25527]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 10:31:29 volumio sudo[25527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:29 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "wizard"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "networkfs"... Mar 24 10:31:29 volumio volumio[25486]: info: Starting Udev Watcher for removable devices Mar 24 10:31:29 volumio volumio[25486]: info: Mounting Device 0ACB-A1DE Mar 24 10:31:29 volumio sudo[25554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/0ACB-A1DE -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:29 volumio sudo[25554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:29 volumio sudo[25554]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:29 volumio volumio[25486]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:29 volumio volumio[25486]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:29 volumio volumio[25486]: error: Failed to mount 0ACB-A1DE: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/0ACB-A1DE" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:29 volumio volumio[25486]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:29 volumio volumio[25486]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:29 volumio volumio[25486]: info: Ignoring mount for partition: boot Mar 24 10:31:29 volumio volumio[25486]: info: Ignoring mount for partition: volumio Mar 24 10:31:29 volumio volumio[25486]: info: Ignoring mount for partition: volumio_data Mar 24 10:31:29 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "volumio_command_line_client"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "upnp"... Mar 24 10:31:29 volumio volumio[25486]: info: [1774348289126] Starting Upmpd Daemon Mar 24 10:31:29 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "my_music"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "mpd"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "upnp_browser"... Mar 24 10:31:29 volumio volumio[25486]: info: Starting UPNP Browser Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "alarm-clock"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "airplay_emulation"... Mar 24 10:31:29 volumio volumio[25486]: info: Starting Shairport Sync Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "last_100"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "webradio"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "i2s_dacs"... Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "volumiodiscovery"... Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** For more information see Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:29 volumio volumio[25486]: *** WARNING *** For more information see Mar 24 10:31:29 volumio node[25486]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:29 volumio node[25486]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:29 volumio node[25486]: *** WARNING *** For more information see Mar 24 10:31:29 volumio node[25486]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:29 volumio node[25486]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:29 volumio node[25486]: *** WARNING *** For more information see Mar 24 10:31:29 volumio volumio[25486]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 10:31:29 volumio volumio[25486]: info: Discovery: Started advertising with name: Volumio Mar 24 10:31:29 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:29 volumio volumio[25486]: info: Loading plugin "spop"... Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "ytmusic"... Mar 24 10:31:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 24 10:31:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:30 volumio go-librespot[25558]: go-librespot daemon starting... Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="app state loaded" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "outputs"... Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "albumart"... Mar 24 10:31:30 volumio volumio[25486]: info: Plugin example_plugin is not enabled Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "inputs"... Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "updater_comm"... Mar 24 10:31:30 volumio volumio[25486]: info: Plugin mpdemulation is not enabled Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "rest_api"... Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "websocket"... Mar 24 10:31:30 volumio volumio[25486]: info: Starting Socket.io Server version 1.7.4 Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "podcast"... Mar 24 10:31:30 volumio volumio[25486]: info: ControllerPodcast::constructor Mar 24 10:31:30 volumio volumio[25486]: info: Loading plugin "rtlsdr_radio"... Mar 24 10:31:30 volumio volumio[25565]: Forking 3 albumart workers Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=info msg="zeroconf server listening on port 34733" Mar 24 10:31:30 volumio volumio[25486]: info: Loading i18n strings for locale en Mar 24 10:31:30 volumio volumio[25486]: Updating browse sources language Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::initPlayerControls Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: Express server listening on port 3000 Mar 24 10:31:30 volumio volumio[25486]: [Metrics] WebUI: 2s 328.90ms Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::resetVolumioState Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::getcurrentVolume Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:30 volumio volumio[25486]: info: Volumio Network Manager: Network status updated: 2 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: Reloading queue from file Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::setRepeat null single undefined Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::pushState Mar 24 10:31:30 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::setRandom true Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::pushState Mar 24 10:31:30 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:30 volumio volumio[25486]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::pushState Mar 24 10:31:30 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:30 volumio volumio[25486]: info: CoreStateMachine::updateTrackBlock Mar 24 10:31:30 volumio volumio[25486]: info: CorePlayQueue::getTrackBlock Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:30 volumio volumio[25486]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 10:31:30 volumio volumio[25486]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Mar 24 10:31:30 volumio volumio[25486]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 10:31:30 volumio volumio[25486]: info: Setting Device type: Raspberry PI Mar 24 10:31:30 volumio volumio[25486]: info: Completed loading Core Plugins Mar 24 10:31:30 volumio volumio[25486]: info: Preparing to generate the ALSA configuration file Mar 24 10:31:30 volumio volumio[25486]: info: Asound.conf file unchanged, so no further update is needed Mar 24 10:31:30 volumio volumio[25486]: info: Output device has changed, restarting MPD Mar 24 10:31:30 volumio volumio[25486]: info: Output device has changed, restarting Shairport Sync Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="obtained new client token: AACIfeWJHC2BwtkCxNxBbN0g2GfcGW6IeHR0znD56x9+IWk+OLLSqSNBjajxfdWNfTgJbC9pZn+QvO4eRs0QkhXLKazaERNBwcX1km1H/V4jENY7w2O4Jn1/mIl/ho29ZmY9kkS8GnbsXLgJjNjFv7Mnk2FX/TTCPcbF5MeyYbxslTAx+Wc5Oiu1J6K78gonh9GX/LT0adS2nCkjLFpaLvS4drbB8oUto0iVm3IFb4AMJDoPF9j1dqwF+w==" Mar 24 10:31:30 volumio sudo[25625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:30 volumio sudo[25625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:30 volumio sudo[25625]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:30 volumio sudo[25626]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:30 volumio sudo[25626]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:30 volumio volumio[25486]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:30 volumio volumio[25486]: info: ___________ START PLUGINS ___________ Mar 24 10:31:30 volumio volumio[25486]: info: ControllerMpd::onStart: Initializing MPD Mar 24 10:31:30 volumio volumio[25486]: info: Creating MPD Configuration file Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:30 volumio volumio[25576]: Starting albumart workers Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:30 volumio volumio[25486]: info: [1774348290854] CoreMusicLibrary::Adding element Media Servers Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:30 volumio sudo[25634]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:30 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 10:31:30 volumio sudo[25634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:30 volumio volumio[25486]: info: UPNP Browser: Client initialized successfully Mar 24 10:31:30 volumio volumio[25577]: Starting albumart workers Mar 24 10:31:30 volumio sudo[25636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:30 volumio sudo[25634]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:30 volumio sudo[25636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:30 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:30 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:30 volumio volumio[25486]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:30 volumio volumio[25486]: info: [1774348290900] CoreMusicLibrary::Adding element Last_100 Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:30 volumio volumio[25486]: info: [1774348290904] CoreMusicLibrary::Adding element Webradio Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:30 volumio volumio[25486]: info: Initializing BBC Radios Mar 24 10:31:30 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:30 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:30 volumio volumio[25578]: Starting albumart workers Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:30 volumio volumio[25486]: info: Creating Spotify config file Mar 24 10:31:30 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="completed keyexchange" Mar 24 10:31:30 volumio go-librespot[25559]: time="2026-03-24T10:31:30Z" level=debug msg="completed challenge" Mar 24 10:31:30 volumio sudo[25655]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 10:31:30 volumio sudo[25655]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 10:31:30 volumio sudo[25655]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio go-librespot[25559]: time="2026-03-24T10:31:31Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:31 volumio volumio[25486]: info: [1774348291140] CoreMusicLibrary::Adding element YouTube Music Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source YouTube Music Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:31 volumio volumio[25486]: info: [1774348291149] CoreMusicLibrary::Adding element Podcast Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source YouTube Music Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source Podcast Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Starting plugin Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Loaded i18n strings for language: en Mar 24 10:31:31 volumio volumio[25486]: info: Volumio Calling Home Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] snd-aloop already loaded Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] No stations database found, creating v2 Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Database loaded at: 2026-03-24T10:31:31.226Z Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Loading blocklist from: /data/plugins/music_service/rtlsdr_radio/blocklist.json Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Got 21 phrases from file Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Updated metadata blocklist Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Metadata module now has 21 phrases Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Management server started on port 3456 Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:31 volumio volumio[25486]: info: [1774348291264] CoreMusicLibrary::Adding element FM/DAB Radio Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source YouTube Music Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source Podcast Mar 24 10:31:31 volumio volumio[25486]: Cannot find translation for source FM/DAB Radio Mar 24 10:31:31 volumio volumio[25486]: info: [RTL-SDR Radio] Plugin started successfully Mar 24 10:31:31 volumio volumio[25486]: info: MPD Permissions set Mar 24 10:31:31 volumio volumio[25486]: info: MPD Permissions set Mar 24 10:31:31 volumio volumio[25486]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:31 volumio volumio[25486]: info: CoreStateMachine::pushState Mar 24 10:31:31 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:31 volumio volumio[25486]: info: Spotify config file written Mar 24 10:31:31 volumio sudo[25694]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 10:31:31 volumio sudo[25694]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:31 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 10:31:31 volumio volumio[25486]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 24 10:31:31 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 10:31:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:31 volumio go-librespot[25696]: go-librespot daemon starting... Mar 24 10:31:31 volumio sudo[25694]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:31 volumio volumio[25486]: info: No need to fix Spotify hosts Mar 24 10:31:31 volumio go-librespot[25704]: time="2026-03-24T10:31:31Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:31 volumio go-librespot[25704]: time="2026-03-24T10:31:31Z" level=debug msg="app state loaded" Mar 24 10:31:31 volumio go-librespot[25704]: time="2026-03-24T10:31:31Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:31 volumio volumio[25486]: info: Starting Shairport Sync Mar 24 10:31:31 volumio volumio[25486]: info: Starting Shairport Sync Mar 24 10:31:31 volumio volumio[25486]: info: Starting Shairport Sync Mar 24 10:31:31 volumio sudo[25714]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:31 volumio sudo[25714]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:31 volumio sudo[25716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:31 volumio sudo[25716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:31 volumio sudo[25718]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:31 volumio sudo[25718]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:31 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 10:31:31 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 10:31:31 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:31 volumio systemd[1]: shairport-sync.service: Consumed 1.546s CPU time. Mar 24 10:31:31 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:31 volumio sudo[25714]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio sudo[25718]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio sudo[25716]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio volumio[25486]: info: Shairport-Sync Started Mar 24 10:31:31 volumio volumio[25486]: Error adding Membership: Error: addMembership EINVAL Mar 24 10:31:31 volumio volumio[25486]: info: Shairport-Sync Started Mar 24 10:31:31 volumio volumio[25486]: info: Shairport-Sync Started Mar 24 10:31:31 volumio volumio[25486]: info: Discovery: adding 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:31 volumio volumio[25486]: info: Discovery: Found device Volumio Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:31 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:31 volumio mpd[25665]: 2026-03-24T10:31:31 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:31 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:31 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 10:31:31 volumio sudo[25626]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio sudo[25636]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:31 volumio volumio[25486]: error: updateQueue error: null Mar 24 10:31:31 volumio volumio[25486]: info: Completed starting Core Plugins Mar 24 10:31:31 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:31 volumio volumio[25486]: info: ----- MyVolumio plugins startup ---- Mar 24 10:31:31 volumio volumio[25486]: info: ------------------------------------------- Mar 24 10:31:31 volumio volumio[25486]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 24 10:31:31 volumio volumio[25486]: error: updateQueue error: null Mar 24 10:31:31 volumio volumio[25486]: info: MPD running with PID25665 Mar 24 10:31:31 volumio volumio[25486]: ,establishing connection Mar 24 10:31:31 volumio volumio[25486]: error: updateQueue error: null Mar 24 10:31:31 volumio volumio[25486]: info: Discovery: this is already registered, 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:31 volumio volumio[25486]: info: Discovery: Found device Volumio Mar 24 10:31:31 volumio volumio[25486]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:31 volumio volumio[25486]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:32 volumio volumio[25486]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 10:31:32 volumio volumio-remote-updater[945]: [2026-03-24 10:31:32] [connect] Successful connection Mar 24 10:31:32 volumio volumio-remote-updater[945]: [2026-03-24 10:31:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774348292 101 Mar 24 10:31:32 volumio volumio[25486]: 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: 2 Mar 24 10:31:32 volumio sudo[25527]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:34 volumio volumio[25486]: info: go-librespot daemon successfully initialized Mar 24 10:31:36 volumio volumio[25486]: info: Volumio called home Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=info msg="zeroconf server listening on port 38053" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="obtained new client token: AACpbESte3Ueqq7fxgZOW6TJ4RnA8ASWPvJZ5MepoJu6ZaKgXqxRZw3YJkHzECBj5QuY+D2xF0apvn5ZlCUsYkmNMPdWb41dst5lnt0s4Wjz4af2HAmUP0ZOKkJYCTGuPlZ+UmaV8ChhiVkqOOVKXcLgj6beyeDj9O6Qu+bvr7dqUCw7ob7ghSpq7iJiUsgI4Fc7bsmdRPb+tlpAqwGesBctcl9pRZXM9BvMAlxqgWsBFO8SbCkX72Hg/w==" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="completed keyexchange" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=debug msg="completed challenge" Mar 24 10:31:36 volumio go-librespot[25704]: time="2026-03-24T10:31:36Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=debug msg="completed keyexchange" Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=debug msg="completed challenge" Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:37 volumio volumio[25486]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=debug msg="new websocket client" Mar 24 10:31:37 volumio volumio[25486]: info: Connection to go-librespot Websocket established Mar 24 10:31:37 volumio go-librespot[25704]: time="2026-03-24T10:31:37Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=debug msg="completed keyexchange" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=debug msg="completed challenge" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=debug msg="completed keyexchange" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=debug msg="completed challenge" Mar 24 10:31:38 volumio go-librespot[25704]: time="2026-03-24T10:31:38Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:39 volumio sudo[25760]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:39 volumio sudo[25760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:39 volumio sudo[25760]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:39 volumio sudo[25762]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:39 volumio sudo[25762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:39 volumio sudo[25764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 10:31:39 volumio sudo[25764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:39 volumio sudo[25762]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:39 volumio sudo[25764]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:39 volumio volumio[25486]: info: Upmpdcli Daemon Started Mar 24 10:31:39 volumio go-librespot[25704]: time="2026-03-24T10:31:39Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:39 volumio go-librespot[25704]: time="2026-03-24T10:31:39Z" level=debug msg="completed keyexchange" Mar 24 10:31:39 volumio go-librespot[25704]: time="2026-03-24T10:31:39Z" level=debug msg="completed challenge" Mar 24 10:31:39 volumio go-librespot[25704]: time="2026-03-24T10:31:39Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin bluetooth to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin multiroom to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin metavolumio to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin cd_controller to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 24 10:31:40 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:40 volumio volumio[25486]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:40 volumio volumio[25486]: info: Starting MyVolumio Remote Streaming Endpoints Mar 24 10:31:40 volumio volumio[25486]: info: MyVolumio login type: Token Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 24 10:31:40 volumio go-librespot[25704]: time="2026-03-24T10:31:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:40 volumio go-librespot[25704]: time="2026-03-24T10:31:40Z" level=debug msg="completed keyexchange" Mar 24 10:31:40 volumio go-librespot[25704]: time="2026-03-24T10:31:40Z" level=debug msg="completed challenge" Mar 24 10:31:40 volumio go-librespot[25704]: time="2026-03-24T10:31:40Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:40 volumio go-librespot[25704]: time="2026-03-24T10:31:40Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 24 10:31:40 volumio volumio[25486]: info: Streaming services startup Mar 24 10:31:40 volumio volumio[25486]: info: Starting Streaming Daemon Mar 24 10:31:40 volumio sudo[25769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:40 volumio sudo[25769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:40 volumio volumio[25486]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 24 10:31:40 volumio sudo[25769]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:40 volumio volumio[25486]: info: Getting Spotify volume Mar 24 10:31:40 volumio volumio[25486]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:40 volumio volumio[25486]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:40 volumio volumio[25486]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 24 10:31:40 volumio volumio[25486]: errno: -111, Mar 24 10:31:40 volumio volumio[25486]: code: 'ECONNREFUSED', Mar 24 10:31:40 volumio volumio[25486]: syscall: 'connect', Mar 24 10:31:40 volumio volumio[25486]: address: '127.0.0.1', Mar 24 10:31:40 volumio volumio[25486]: port: 9879, Mar 24 10:31:40 volumio volumio[25486]: response: undefined Mar 24 10:31:40 volumio volumio[25486]: } Mar 24 10:31:40 volumio volumio[25486]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:40 volumio sudo[25789]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 10:30' Mar 24 10:31:40 volumio sudo[25789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:40 volumio sudo[25789]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:41 volumio volumio-remote-updater[945]: [2026-03-24 10:31:41] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 10:31:41 volumio volumio-remote-updater[945]: [2026-03-24 10:31:41] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 10:31:41 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:41 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 10:31:41 volumio systemd[1]: volumio.service: Consumed 8.534s CPU time. Mar 24 10:31:41 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:41 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:41 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 78081. Mar 24 10:31:41 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:41 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 10:31:41 volumio systemd[1]: volumio.service: Consumed 8.534s CPU time. Mar 24 10:31:41 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 10:31:41 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:41 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:41 volumio volumio[25801]: info: ----- Volumio3 ---- Mar 24 10:31:41 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:41 volumio volumio[25801]: info: ----- System startup ---- Mar 24 10:31:41 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:41 volumio volumio[25801]: info: MYVOLUMIO Environment detected Mar 24 10:31:41 volumio volumio[25801]: info: Plugin folders cleanup Mar 24 10:31:41 volumio volumio[25801]: info: Scanning into folder /volumio/app/plugins/ Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category audio_interface Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category miscellanea Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category music_service Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category plugins.json Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category system_controller Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category user_interface Mar 24 10:31:41 volumio volumio[25801]: info: Scanning into folder /data/plugins/ Mar 24 10:31:41 volumio volumio[25801]: info: Scanning category music_service Mar 24 10:31:41 volumio volumio[25801]: info: Plugin folders cleanup completed Mar 24 10:31:41 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:41 volumio volumio[25801]: info: ----- Core plugins startup ---- Mar 24 10:31:41 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:41 volumio volumio[25801]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 10:31:41 volumio volumio[25801]: info: Adding plugin upnp to MyMusic Plugins Mar 24 10:31:41 volumio volumio[25801]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 10:31:41 volumio volumio[25801]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 10:31:41 volumio volumio[25801]: info: Loading plugins from folder /data/plugins/ Mar 24 10:31:41 volumio volumio[25801]: info: Adding plugin rtlsdr_radio to MyMusic Plugins Mar 24 10:31:41 volumio volumio[25801]: info: Loading plugin "system"... Mar 24 10:31:41 volumio volumio[25801]: info: Loading plugin "appearance"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "network"... Mar 24 10:31:42 volumio volumio[25801]: info: Refreshing Cached IP Addresses Mar 24 10:31:42 volumio sudo[25829]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:42 volumio sudo[25829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:42 volumio sudo[25831]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:42 volumio sudo[25831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:42 volumio sudo[25829]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:42 volumio sudo[25831]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "services"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "alsa_controller"... Mar 24 10:31:42 volumio sudo[25838]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 10:31:42 volumio sudo[25838]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:42 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "wizard"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "networkfs"... Mar 24 10:31:42 volumio volumio[25801]: info: Starting Udev Watcher for removable devices Mar 24 10:31:42 volumio volumio[25801]: info: Mounting Device 0ACB-A1DE Mar 24 10:31:42 volumio sudo[25868]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/0ACB-A1DE -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:42 volumio sudo[25868]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:42 volumio sudo[25868]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:42 volumio volumio[25801]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:42 volumio volumio[25801]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:42 volumio volumio[25801]: error: Failed to mount 0ACB-A1DE: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/0ACB-A1DE" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:42 volumio volumio[25801]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:42 volumio volumio[25801]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:42 volumio volumio[25801]: info: Ignoring mount for partition: boot Mar 24 10:31:42 volumio volumio[25801]: info: Ignoring mount for partition: volumio Mar 24 10:31:42 volumio volumio[25801]: info: Ignoring mount for partition: volumio_data Mar 24 10:31:42 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "volumio_command_line_client"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "upnp"... Mar 24 10:31:42 volumio volumio[25801]: info: [1774348302368] Starting Upmpd Daemon Mar 24 10:31:42 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "my_music"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "mpd"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "upnp_browser"... Mar 24 10:31:42 volumio volumio[25801]: info: Starting UPNP Browser Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "alarm-clock"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "airplay_emulation"... Mar 24 10:31:42 volumio volumio[25801]: info: Starting Shairport Sync Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "last_100"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "webradio"... Mar 24 10:31:42 volumio volumio[25801]: info: Loading plugin "i2s_dacs"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "volumiodiscovery"... Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** For more information see Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:43 volumio volumio[25801]: *** WARNING *** For more information see Mar 24 10:31:43 volumio node[25801]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:43 volumio node[25801]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:43 volumio node[25801]: *** WARNING *** For more information see Mar 24 10:31:43 volumio node[25801]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:43 volumio node[25801]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:43 volumio node[25801]: *** WARNING *** For more information see Mar 24 10:31:43 volumio volumio[25801]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 10:31:43 volumio volumio[25801]: info: Discovery: Started advertising with name: Volumio Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "spop"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "ytmusic"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "outputs"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "albumart"... Mar 24 10:31:43 volumio volumio[25801]: info: Plugin example_plugin is not enabled Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "inputs"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "updater_comm"... Mar 24 10:31:43 volumio volumio[25801]: info: Plugin mpdemulation is not enabled Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "rest_api"... Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "websocket"... Mar 24 10:31:43 volumio volumio[25801]: info: Starting Socket.io Server version 1.7.4 Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "podcast"... Mar 24 10:31:43 volumio volumio[25801]: info: ControllerPodcast::constructor Mar 24 10:31:43 volumio volumio[25801]: info: Loading plugin "rtlsdr_radio"... Mar 24 10:31:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 10:31:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:43 volumio volumio[25872]: Forking 3 albumart workers Mar 24 10:31:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:43 volumio go-librespot[25882]: go-librespot daemon starting... Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=debug msg="app state loaded" Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:43 volumio volumio[25801]: info: Loading i18n strings for locale en Mar 24 10:31:43 volumio volumio[25801]: Updating browse sources language Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::initPlayerControls Mar 24 10:31:43 volumio go-librespot[25883]: time="2026-03-24T10:31:43Z" level=info msg="zeroconf server listening on port 45987" Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:43 volumio volumio[25801]: Express server listening on port 3000 Mar 24 10:31:43 volumio volumio[25801]: [Metrics] WebUI: 2s 348.87ms Mar 24 10:31:43 volumio volumio[25801]: info: CoreStateMachine::resetVolumioState Mar 24 10:31:43 volumio volumio[25801]: info: CoreStateMachine::getcurrentVolume Mar 24 10:31:43 volumio volumio[25801]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:43 volumio volumio[25801]: info: Volumio Network Manager: Network status updated: 2 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: Reloading queue from file Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::setRepeat null single undefined Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::pushState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::setRandom true Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::pushState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:44 volumio volumio[25801]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::pushState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::updateTrackBlock Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrackBlock Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:31:44 volumio volumio[25801]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 10:31:44 volumio volumio[25801]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Mar 24 10:31:44 volumio volumio[25801]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 10:31:44 volumio volumio[25801]: info: Setting Device type: Raspberry PI Mar 24 10:31:44 volumio volumio[25801]: info: Completed loading Core Plugins Mar 24 10:31:44 volumio volumio[25801]: info: Preparing to generate the ALSA configuration file Mar 24 10:31:44 volumio volumio[25801]: info: Asound.conf file unchanged, so no further update is needed Mar 24 10:31:44 volumio volumio[25801]: info: Output device has changed, restarting MPD Mar 24 10:31:44 volumio volumio[25801]: info: Output device has changed, restarting Shairport Sync Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio sudo[25938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:44 volumio sudo[25938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio sudo[25938]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio volumio[25893]: Starting albumart workers Mar 24 10:31:44 volumio sudo[25940]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:44 volumio sudo[25940]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio volumio[25801]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:44 volumio volumio[25801]: info: ___________ START PLUGINS ___________ Mar 24 10:31:44 volumio volumio[25801]: info: ControllerMpd::onStart: Initializing MPD Mar 24 10:31:44 volumio volumio[25801]: info: Creating MPD Configuration file Mar 24 10:31:44 volumio volumio[25890]: Starting albumart workers Mar 24 10:31:44 volumio sudo[25948]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:31:44 volumio sudo[25948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio sudo[25948]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304154] CoreMusicLibrary::Adding element Media Servers Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio volumio[25801]: info: UPNP Browser: Client initialized successfully Mar 24 10:31:44 volumio sudo[25952]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:31:44 volumio sudo[25952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:44 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:44 volumio volumio[25801]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304204] CoreMusicLibrary::Adding element Last_100 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304210] CoreMusicLibrary::Adding element Webradio Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:44 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:44 volumio volumio[25801]: info: Initializing BBC Radios Mar 24 10:31:44 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:31:44 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:31:44 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:31:44 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:31:44 volumio go-librespot[25883]: time="2026-03-24T10:31:44Z" level=debug msg="obtained new client token: AAC0s57EOyh4hcwMGSEtVuUs/kPwem6OliUZSDA6BEQ/xfoaGOpQcRcGHuQ8tVqfAwAqHUHrMLHzhgsJB0cDC3RVmTvAvCF7Z9tdGRv7nITl8fhuLbMRJin4HXqI60PMJoYDm1Y0/J2FO+PSZn1EHSmHkKSANsRZlXoceI5h3W0zzb9fL4GKHhXXPRwHSB+sQe1XzxDgH6d1+EUh8yP4LH4E2nJBzYeNZFpnMKzI21XjxmtSj81i3/k=" Mar 24 10:31:44 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio volumio[25886]: Starting albumart workers Mar 24 10:31:44 volumio volumio[25801]: info: Creating Spotify config file Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio sudo[25973]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 10:31:44 volumio sudo[25973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 10:31:44 volumio sudo[25973]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio go-librespot[25883]: time="2026-03-24T10:31:44Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:44 volumio go-librespot[25883]: time="2026-03-24T10:31:44Z" level=debug msg="completed keyexchange" Mar 24 10:31:44 volumio go-librespot[25883]: time="2026-03-24T10:31:44Z" level=debug msg="completed challenge" Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304453] CoreMusicLibrary::Adding element YouTube Music Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source YouTube Music Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304457] CoreMusicLibrary::Adding element Podcast Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source YouTube Music Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source Podcast Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Starting plugin Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Loaded i18n strings for language: en Mar 24 10:31:44 volumio volumio[25801]: info: Volumio Calling Home Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] snd-aloop already loaded Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] No stations database found, creating v2 Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Database loaded at: 2026-03-24T10:31:44.519Z Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Loading blocklist from: /data/plugins/music_service/rtlsdr_radio/blocklist.json Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Got 21 phrases from file Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Updated metadata blocklist Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Metadata module now has 21 phrases Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Management server started on port 3456 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:31:44 volumio volumio[25801]: info: [1774348304553] CoreMusicLibrary::Adding element FM/DAB Radio Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source YouTube Music Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source Podcast Mar 24 10:31:44 volumio volumio[25801]: Cannot find translation for source FM/DAB Radio Mar 24 10:31:44 volumio volumio[25801]: info: [RTL-SDR Radio] Plugin started successfully Mar 24 10:31:44 volumio volumio[25801]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:31:44 volumio volumio[25801]: info: CoreStateMachine::pushState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioPushState Mar 24 10:31:44 volumio go-librespot[25883]: time="2026-03-24T10:31:44Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:44 volumio volumio[25801]: info: Discovery: adding 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:44 volumio volumio[25801]: info: Discovery: Found device Volumio Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: Discovery: this is already registered, 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:31:44 volumio volumio[25801]: info: Discovery: Found device Volumio Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio volumio[25801]: info: MPD Permissions set Mar 24 10:31:44 volumio volumio[25801]: info: MPD Permissions set Mar 24 10:31:44 volumio volumio[25801]: info: Spotify config file written Mar 24 10:31:44 volumio sudo[26008]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 10:31:44 volumio sudo[26008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 10:31:44 volumio volumio[25801]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio go-librespot[26012]: go-librespot daemon starting... Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:31:44 volumio volumio[25801]: info: No need to fix Spotify hosts Mar 24 10:31:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:44 volumio sudo[26008]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio go-librespot[26021]: time="2026-03-24T10:31:44Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:44 volumio go-librespot[26021]: time="2026-03-24T10:31:44Z" level=debug msg="app state loaded" Mar 24 10:31:44 volumio go-librespot[26021]: time="2026-03-24T10:31:44Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:44 volumio volumio[25801]: info: Starting Shairport Sync Mar 24 10:31:44 volumio volumio[25801]: info: Starting Shairport Sync Mar 24 10:31:44 volumio volumio[25801]: info: Starting Shairport Sync Mar 24 10:31:44 volumio sudo[26028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:44 volumio sudo[26028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio sudo[26030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:44 volumio sudo[26030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio sudo[26032]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:31:44 volumio sudo[26032]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:44 volumio volumio[25801]: info: CoreCommandRouter::volumioGetState Mar 24 10:31:44 volumio volumio[25801]: info: CorePlayQueue::getTrack 0 Mar 24 10:31:44 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 10:31:44 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 10:31:44 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:44 volumio systemd[1]: shairport-sync.service: Consumed 1.543s CPU time. Mar 24 10:31:44 volumio volumio[25801]: info: Volumio called home Mar 24 10:31:44 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:31:44 volumio sudo[26028]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio sudo[26030]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio sudo[26032]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:44 volumio volumio[25801]: info: Shairport-Sync Started Mar 24 10:31:44 volumio volumio[25801]: Error adding Membership: Error: addMembership EINVAL Mar 24 10:31:44 volumio volumio[25801]: info: Shairport-Sync Started Mar 24 10:31:44 volumio volumio[25801]: info: Shairport-Sync Started Mar 24 10:31:44 volumio volumio[25801]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 10:31:45 volumio mpd[25980]: 2026-03-24T10:31:45 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 10:31:45 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 10:31:45 volumio sudo[25940]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:45 volumio sudo[25952]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:45 volumio volumio[25801]: error: updateQueue error: null Mar 24 10:31:45 volumio volumio[25801]: info: Completed starting Core Plugins Mar 24 10:31:45 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:45 volumio volumio[25801]: info: ----- MyVolumio plugins startup ---- Mar 24 10:31:45 volumio volumio[25801]: info: ------------------------------------------- Mar 24 10:31:45 volumio volumio[25801]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 24 10:31:45 volumio volumio[25801]: info: MPD running with PID25980 Mar 24 10:31:45 volumio volumio[25801]: ,establishing connection Mar 24 10:31:45 volumio volumio[25801]: error: updateQueue error: null Mar 24 10:31:45 volumio volumio[25801]: error: updateQueue error: null Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=info msg="zeroconf server listening on port 43445" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="obtained new client token: AAACtV9BELQTP0y8Gzyd/4bbI4P2xpG0kdZm6YguCY2NfPqqjNXBvInFvu7zQpQ4IWElYyEIoG8uFBqoKmy7agt7zAq1iu5ncg/WDF4/PaAAFOb8DKP62Yy2lgPmAD5tFh9tPlv5Oe5loHl/GtNsNBmkjRD13DiaHhWgMCHDHsXIAE8pSDSO49SoR4mvOnCgRXJC6yuI6aIk9UvRDPSy/R37+GebFfh4zUS68WeYaze+XIjrKSu1n4iwbQ==" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="completed keyexchange" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=debug msg="completed challenge" Mar 24 10:31:45 volumio go-librespot[26021]: time="2026-03-24T10:31:45Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:45 volumio sudo[25838]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:46 volumio volumio-remote-updater[945]: [2026-03-24 10:31:46] [connect] Successful connection Mar 24 10:31:46 volumio volumio-remote-updater[945]: [2026-03-24 10:31:46] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774348306 101 Mar 24 10:31:46 volumio volumio[25801]: 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: 2 Mar 24 10:31:46 volumio go-librespot[26021]: time="2026-03-24T10:31:46Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:46 volumio go-librespot[26021]: time="2026-03-24T10:31:46Z" level=debug msg="completed keyexchange" Mar 24 10:31:46 volumio go-librespot[26021]: time="2026-03-24T10:31:46Z" level=debug msg="completed challenge" Mar 24 10:31:46 volumio go-librespot[26021]: time="2026-03-24T10:31:46Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="completed keyexchange" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="completed challenge" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:47 volumio volumio[25801]: info: go-librespot daemon successfully initialized Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="completed keyexchange" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=debug msg="completed challenge" Mar 24 10:31:47 volumio go-librespot[26021]: time="2026-03-24T10:31:47Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: failed peeking unencrypted bytes: failed peeking uncrypted: EOF" Mar 24 10:31:48 volumio go-librespot[26021]: time="2026-03-24T10:31:48Z" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 24 10:31:48 volumio go-librespot[26021]: time="2026-03-24T10:31:48Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:48 volumio go-librespot[26021]: time="2026-03-24T10:31:48Z" level=debug msg="completed keyexchange" Mar 24 10:31:48 volumio go-librespot[26021]: time="2026-03-24T10:31:48Z" level=debug msg="completed challenge" Mar 24 10:31:48 volumio go-librespot[26021]: time="2026-03-24T10:31:48Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:49 volumio go-librespot[26021]: time="2026-03-24T10:31:49Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:31:49 volumio go-librespot[26021]: time="2026-03-24T10:31:49Z" level=debug msg="completed keyexchange" Mar 24 10:31:49 volumio go-librespot[26021]: time="2026-03-24T10:31:49Z" level=debug msg="completed challenge" Mar 24 10:31:49 volumio go-librespot[26021]: time="2026-03-24T10:31:49Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:49 volumio go-librespot[26021]: time="2026-03-24T10:31:49Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:50 volumio volumio[25801]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:50 volumio volumio[25801]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:52 volumio sudo[26075]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:52 volumio sudo[26075]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:52 volumio sudo[26077]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:52 volumio sudo[26077]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:52 volumio sudo[26075]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:52 volumio sudo[26077]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:52 volumio sudo[26080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 10:31:52 volumio sudo[26080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 10:31:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:31:52 volumio go-librespot[26083]: go-librespot daemon starting... Mar 24 10:31:52 volumio sudo[26080]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:52 volumio volumio[25801]: info: Upmpdcli Daemon Started Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="app state loaded" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=info msg="zeroconf server listening on port 34577" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="obtained new client token: AABTnJBqOwtFPdwug8fwgfABi9icuw9Ancu+TjofoSfKtFnO0m59tedS67+Og2GxDw1ey4tZqpPqZXTRs0rEHnUaP69MOe5hawM/eEK/9ewymerUaQzECVS8bbFzLSK4xAB9QOELHZ+YaM+oGg7ShGgsBygBLmyCpnDNt6hm/RDwAhwBpt81f2usT5mWcIAKXZbUI2KUJuhlireI8UlF/+oTW4SpHj35PWff/z6IJxxNlCl/qQ+ny5XyNw==" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="completed keyexchange" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=debug msg="completed challenge" Mar 24 10:31:52 volumio go-librespot[26084]: time="2026-03-24T10:31:52Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=debug msg="completed keyexchange" Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=debug msg="completed challenge" Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin bluetooth to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin multiroom to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin metavolumio to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin cd_controller to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 24 10:31:53 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:53 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:53 volumio volumio[25801]: info: Starting MyVolumio Remote Streaming Endpoints Mar 24 10:31:53 volumio volumio[25801]: info: MyVolumio login type: Token Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 24 10:31:53 volumio volumio[25801]: info: Streaming services startup Mar 24 10:31:53 volumio volumio[25801]: info: Starting Streaming Daemon Mar 24 10:31:53 volumio sudo[26094]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:53 volumio sudo[26094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:53 volumio volumio[25801]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 24 10:31:53 volumio sudo[26094]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:53 volumio volumio[25801]: info: Initializing connection to go-librespot Websocket Mar 24 10:31:53 volumio volumio[25801]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:53 volumio volumio[25801]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:53 volumio volumio[25801]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:53 volumio go-librespot[26084]: time="2026-03-24T10:31:53Z" level=debug msg="new websocket client" Mar 24 10:31:53 volumio volumio[25801]: info: Connection to go-librespot Websocket established Mar 24 10:31:54 volumio go-librespot[26084]: time="2026-03-24T10:31:54Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:31:54 volumio go-librespot[26084]: time="2026-03-24T10:31:54Z" level=debug msg="completed keyexchange" Mar 24 10:31:54 volumio go-librespot[26084]: time="2026-03-24T10:31:54Z" level=debug msg="completed challenge" Mar 24 10:31:54 volumio go-librespot[26084]: time="2026-03-24T10:31:54Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:54 volumio volumio[25801]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 24 10:31:54 volumio volumio[25801]: info: MyVolumio token set successfully Mar 24 10:31:54 volumio volumio[25801]: info: MYVOLUMIO: Adding device Mar 24 10:31:54 volumio volumio[25801]: info: MYVOLUMIO: Evaluating Server Mar 24 10:31:54 volumio volumio[25801]: info: MyVolumio status changed Mar 24 10:31:54 volumio volumio[25801]: info: Streaming services startup Mar 24 10:31:54 volumio volumio[25801]: info: Starting Streaming Daemon Mar 24 10:31:54 volumio volumio[25801]: info: Removing browser output: myVolumio user plan is not superstar Mar 24 10:31:54 volumio volumio[25801]: info: Removing audio output: Mar 24 10:31:54 volumio volumio[25801]: info: Stoppping Tunnel 1 Mar 24 10:31:54 volumio sudo[26121]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:31:54 volumio sudo[26121]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:54 volumio sudo[26123]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 24 10:31:54 volumio sudo[26123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio sudo[26121]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio volumio[25801]: error: Cannot start Volumio Streaming Daemon Mar 24 10:31:54 volumio volumio[25801]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:31:54 volumio volumio[25801]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:31:54 volumio sudo[26123]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:54 volumio volumio[25801]: info: Remote SSH Stopped Mar 24 10:31:54 volumio go-librespot[26084]: time="2026-03-24T10:31:54Z" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 10:31:55 volumio go-librespot[26084]: time="2026-03-24T10:31:55Z" level=debug msg="completed keyexchange" Mar 24 10:31:55 volumio go-librespot[26084]: time="2026-03-24T10:31:55Z" level=debug msg="completed challenge" Mar 24 10:31:55 volumio go-librespot[26084]: time="2026-03-24T10:31:55Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:55 volumio volumio[25801]: info: Setting Geolocation for MyVolumio to eu3 Mar 24 10:31:55 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:55 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:55 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:55 volumio volumio[25801]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 24 10:31:55 volumio go-librespot[26084]: time="2026-03-24T10:31:55Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=debug msg="completed keyexchange" Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=debug msg="completed challenge" Mar 24 10:31:56 volumio volumio[25801]: info: Updating MyVolumio device info Mar 24 10:31:56 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:56 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:56 volumio volumio[25801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:56 volumio volumio[25801]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=debug msg="completed keyexchange" Mar 24 10:31:56 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=debug msg="completed challenge" Mar 24 10:31:57 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:57 volumio go-librespot[26084]: time="2026-03-24T10:31:56Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:31:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:31:57 volumio volumio[25801]: info: Getting Spotify volume Mar 24 10:31:57 volumio volumio[25801]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:57 volumio volumio[25801]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:31:57 volumio volumio[25801]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 24 10:31:57 volumio volumio[25801]: errno: -111, Mar 24 10:31:57 volumio volumio[25801]: code: 'ECONNREFUSED', Mar 24 10:31:57 volumio volumio[25801]: syscall: 'connect', Mar 24 10:31:57 volumio volumio[25801]: address: '127.0.0.1', Mar 24 10:31:57 volumio volumio[25801]: port: 9879, Mar 24 10:31:57 volumio volumio[25801]: response: undefined Mar 24 10:31:57 volumio volumio[25801]: } Mar 24 10:31:57 volumio volumio[25801]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:31:57 volumio sudo[26140]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 10:30' Mar 24 10:31:57 volumio sudo[26140]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:57 volumio sudo[26140]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:57 volumio volumio-remote-updater[945]: [2026-03-24 10:31:57] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 24 10:31:57 volumio volumio-remote-updater[945]: [2026-03-24 10:31:57] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 24 10:31:57 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:31:57 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 24 10:31:57 volumio systemd[1]: volumio.service: Consumed 8.991s CPU time. Mar 24 10:31:57 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:57 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:57 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 78082. Mar 24 10:31:57 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 24 10:31:57 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 24 10:31:57 volumio systemd[1]: volumio.service: Consumed 8.991s CPU time. Mar 24 10:31:57 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Mar 24 10:31:57 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Mar 24 10:31:58 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:31:58 volumio volumio[26155]: info: ----- Volumio3 ---- Mar 24 10:31:58 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:31:58 volumio volumio[26155]: info: ----- System startup ---- Mar 24 10:31:58 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:31:58 volumio volumio[26155]: info: MYVOLUMIO Environment detected Mar 24 10:31:58 volumio volumio[26155]: info: Plugin folders cleanup Mar 24 10:31:58 volumio volumio[26155]: info: Scanning into folder /volumio/app/plugins/ Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category audio_interface Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category miscellanea Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category music_service Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category plugins.json Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category system_controller Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category user_interface Mar 24 10:31:58 volumio volumio[26155]: info: Scanning into folder /data/plugins/ Mar 24 10:31:58 volumio volumio[26155]: info: Scanning category music_service Mar 24 10:31:58 volumio volumio[26155]: info: Plugin folders cleanup completed Mar 24 10:31:58 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:31:58 volumio volumio[26155]: info: ----- Core plugins startup ---- Mar 24 10:31:58 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugins from folder /volumio/app/plugins/ Mar 24 10:31:58 volumio volumio[26155]: info: Adding plugin upnp to MyMusic Plugins Mar 24 10:31:58 volumio volumio[26155]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 24 10:31:58 volumio volumio[26155]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugins from folder /data/plugins/ Mar 24 10:31:58 volumio volumio[26155]: info: Adding plugin rtlsdr_radio to MyMusic Plugins Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "system"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "appearance"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "network"... Mar 24 10:31:58 volumio volumio[26155]: info: Refreshing Cached IP Addresses Mar 24 10:31:58 volumio sudo[26185]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:31:58 volumio sudo[26185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:58 volumio sudo[26187]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:31:58 volumio sudo[26187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:58 volumio sudo[26185]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:58 volumio sudo[26187]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "services"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "alsa_controller"... Mar 24 10:31:58 volumio sudo[26196]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 24 10:31:58 volumio sudo[26196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:58 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "wizard"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "networkfs"... Mar 24 10:31:58 volumio volumio[26155]: info: Starting Udev Watcher for removable devices Mar 24 10:31:58 volumio volumio[26155]: info: Mounting Device 0ACB-A1DE Mar 24 10:31:58 volumio sudo[26224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/0ACB-A1DE -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:58 volumio sudo[26224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:31:58 volumio sudo[26224]: pam_unix(sudo:session): session closed for user root Mar 24 10:31:58 volumio volumio[26155]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:58 volumio volumio[26155]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:58 volumio volumio[26155]: error: Failed to mount 0ACB-A1DE: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/0ACB-A1DE" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 24 10:31:58 volumio volumio[26155]: mount: /media/0ACB-A1DE: /dev/sda1 already mounted on /media/0ACB-A1DE. Mar 24 10:31:58 volumio volumio[26155]: dmesg(1) may have more information after failed mount system call. Mar 24 10:31:58 volumio volumio[26155]: info: Ignoring mount for partition: boot Mar 24 10:31:58 volumio volumio[26155]: info: Ignoring mount for partition: volumio Mar 24 10:31:58 volumio volumio[26155]: info: Ignoring mount for partition: volumio_data Mar 24 10:31:58 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "volumio_command_line_client"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "upnp"... Mar 24 10:31:58 volumio volumio[26155]: info: [1774348318869] Starting Upmpd Daemon Mar 24 10:31:58 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "my_music"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "mpd"... Mar 24 10:31:58 volumio volumio[26155]: info: Loading plugin "upnp_browser"... Mar 24 10:31:59 volumio volumio[26155]: info: Starting UPNP Browser Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "alarm-clock"... Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "airplay_emulation"... Mar 24 10:31:59 volumio volumio[26155]: info: Starting Shairport Sync Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "last_100"... Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "webradio"... Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "i2s_dacs"... Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "volumiodiscovery"... Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** For more information see Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:59 volumio volumio[26155]: *** WARNING *** For more information see Mar 24 10:31:59 volumio node[26155]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:59 volumio node[26155]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:59 volumio node[26155]: *** WARNING *** For more information see Mar 24 10:31:59 volumio node[26155]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 24 10:31:59 volumio node[26155]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 24 10:31:59 volumio node[26155]: *** WARNING *** For more information see Mar 24 10:31:59 volumio volumio[26155]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 24 10:31:59 volumio volumio[26155]: info: Discovery: Started advertising with name: Volumio Mar 24 10:31:59 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "spop"... Mar 24 10:31:59 volumio volumio[26155]: info: Loading plugin "ytmusic"... Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "outputs"... Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "albumart"... Mar 24 10:32:00 volumio volumio[26155]: info: Plugin example_plugin is not enabled Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "inputs"... Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "updater_comm"... Mar 24 10:32:00 volumio volumio[26155]: info: Plugin mpdemulation is not enabled Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "rest_api"... Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "websocket"... Mar 24 10:32:00 volumio volumio[26155]: info: Starting Socket.io Server version 1.7.4 Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "podcast"... Mar 24 10:32:00 volumio volumio[26155]: info: ControllerPodcast::constructor Mar 24 10:32:00 volumio volumio[26155]: info: Loading plugin "rtlsdr_radio"... Mar 24 10:32:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 24 10:32:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:00 volumio volumio[26228]: Forking 3 albumart workers Mar 24 10:32:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:00 volumio go-librespot[26238]: go-librespot daemon starting... Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="app state loaded" Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:32:00 volumio volumio[26155]: info: Loading i18n strings for locale en Mar 24 10:32:00 volumio volumio[26155]: Updating browse sources language Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::initPlayerControls Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: Express server listening on port 3000 Mar 24 10:32:00 volumio volumio[26155]: [Metrics] WebUI: 2s 342.15ms Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=info msg="zeroconf server listening on port 36331" Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::resetVolumioState Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::getcurrentVolume Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:32:00 volumio volumio[26155]: info: Volumio Network Manager: Network status updated: 2 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: Reloading queue from file Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::setRepeat null single undefined Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::pushState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioPushState Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::setRandom true Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::pushState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioPushState Mar 24 10:32:00 volumio volumio[26155]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::pushState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioPushState Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::updateTrackBlock Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrackBlock Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioRetrievevolume Mar 24 10:32:00 volumio volumio[26155]: info: Setting Device type: Raspberry PI Mar 24 10:32:00 volumio volumio[26155]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 24 10:32:00 volumio volumio[26155]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Mar 24 10:32:00 volumio volumio[26155]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 24 10:32:00 volumio volumio[26155]: info: Completed loading Core Plugins Mar 24 10:32:00 volumio volumio[26155]: info: Preparing to generate the ALSA configuration file Mar 24 10:32:00 volumio volumio[26155]: info: Asound.conf file unchanged, so no further update is needed Mar 24 10:32:00 volumio volumio[26155]: info: Output device has changed, restarting MPD Mar 24 10:32:00 volumio volumio[26155]: info: Output device has changed, restarting Shairport Sync Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:32:00 volumio volumio[26155]: info: ___________ START PLUGINS ___________ Mar 24 10:32:00 volumio volumio[26155]: info: ControllerMpd::onStart: Initializing MPD Mar 24 10:32:00 volumio volumio[26155]: info: Creating MPD Configuration file Mar 24 10:32:00 volumio sudo[26295]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:32:00 volumio sudo[26295]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:00 volumio sudo[26297]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320589] CoreMusicLibrary::Adding element Media Servers Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio sudo[26295]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:00 volumio sudo[26297]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:00 volumio sudo[26305]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 24 10:32:00 volumio sudo[26305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:00 volumio volumio[26155]: info: UPNP Browser: Client initialized successfully Mar 24 10:32:00 volumio sudo[26303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 24 10:32:00 volumio sudo[26303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:00 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 24 10:32:00 volumio sudo[26303]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:00 volumio systemd[1]: mpd.service: Deactivated successfully. Mar 24 10:32:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 24 10:32:00 volumio systemd[1]: mpd.socket: Deactivated successfully. Mar 24 10:32:00 volumio volumio[26155]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:32:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 24 10:32:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:00 volumio volumio[26246]: Starting albumart workers Mar 24 10:32:00 volumio volumio[26155]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320665] CoreMusicLibrary::Adding element Last_100 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320667] CoreMusicLibrary::Adding element Webradio Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:32:00 volumio volumio[26155]: info: Initializing BBC Radios Mar 24 10:32:00 volumio volumio[26248]: Starting albumart workers Mar 24 10:32:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 24 10:32:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Mar 24 10:32:00 volumio volumio[26247]: Starting albumart workers Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:00 volumio volumio[26155]: info: Creating Spotify config file Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:00 volumio sudo[26327]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 24 10:32:00 volumio sudo[26327]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 24 10:32:00 volumio sudo[26327]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320828] CoreMusicLibrary::Adding element YouTube Music Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source YouTube Music Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320833] CoreMusicLibrary::Adding element Podcast Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source YouTube Music Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source Podcast Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Starting plugin Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Loaded i18n strings for language: en Mar 24 10:32:00 volumio volumio[26155]: info: Volumio Calling Home Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] snd-aloop already loaded Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] No stations database found, creating v2 Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Database loaded at: 2026-03-24T10:32:00.882Z Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Loading blocklist from: /data/plugins/music_service/rtlsdr_radio/blocklist.json Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Got 21 phrases from file Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Updated metadata blocklist Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Metadata module now has 21 phrases Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="obtained new client token: AADM62R/mmd5PO2td/M1Pk4344/QmkKC+86daUSSCiMgtObIjcMYbLFvFXlrY9xUyry0Sz2/9U9WWuOo4urAIzrFjm6J6+g5sg1TNXLyJzlAw2mTfCVQ7Q3yXt5hIHSDcTnWLijZoMd/nmiOXrzXwK+T8Gil7CVZ2X6ue0wIF244w/hu1DdgUSx8RuFx13jdXWuBeEcRLhKTxXTkgZq6Yviv7kmEY3YV9bnwtFq8e4MN6s7S7UPZYhIr4Q==" Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Management server started on port 3456 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 24 10:32:00 volumio volumio[26155]: info: [1774348320931] CoreMusicLibrary::Adding element FM/DAB Radio Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source YouTube Music Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source Podcast Mar 24 10:32:00 volumio volumio[26155]: Cannot find translation for source FM/DAB Radio Mar 24 10:32:00 volumio volumio[26155]: info: [RTL-SDR Radio] Plugin started successfully Mar 24 10:32:00 volumio go-librespot[26239]: time="2026-03-24T10:32:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:32:00 volumio volumio[26155]: info: Discovery: adding 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:32:00 volumio volumio[26155]: info: Discovery: Found device Volumio Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioGetState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: Discovery: this is already registered, 072f109f-54a2-4344-b8c4-538b45da7e51 Mar 24 10:32:00 volumio volumio[26155]: info: Discovery: Found device Volumio Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioGetState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: MPD Permissions set Mar 24 10:32:00 volumio volumio[26155]: info: MPD Permissions set Mar 24 10:32:00 volumio volumio[26155]: info: VolumeController:: Volume=36 Mute =true Mar 24 10:32:00 volumio volumio[26155]: info: CoreStateMachine::pushState Mar 24 10:32:00 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:00 volumio volumio[26155]: info: CoreCommandRouter::volumioPushState Mar 24 10:32:00 volumio volumio[26155]: info: Spotify config file written Mar 24 10:32:01 volumio sudo[26354]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 24 10:32:01 volumio sudo[26354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:01 volumio volumio[26155]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 24 10:32:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 24 10:32:01 volumio volumio[26155]: info: No need to fix Spotify hosts Mar 24 10:32:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:01 volumio go-librespot[26362]: go-librespot daemon starting... Mar 24 10:32:01 volumio sudo[26354]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio volumio[26155]: info: Starting Shairport Sync Mar 24 10:32:01 volumio volumio[26155]: info: Starting Shairport Sync Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=debug msg="app state loaded" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:32:01 volumio volumio[26155]: info: Starting Shairport Sync Mar 24 10:32:01 volumio volumio[26155]: info: Volumio called home Mar 24 10:32:01 volumio sudo[26374]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:32:01 volumio sudo[26374]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:01 volumio sudo[26376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:32:01 volumio sudo[26376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:01 volumio sudo[26379]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 24 10:32:01 volumio sudo[26379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:01 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 10:32:01 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 10:32:01 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:32:01 volumio systemd[1]: shairport-sync.service: Consumed 1.545s CPU time. Mar 24 10:32:01 volumio volumio[26155]: info: CoreCommandRouter::volumioGetState Mar 24 10:32:01 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:01 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:32:01 volumio sudo[26376]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio volumio[26155]: info: Shairport-Sync Started Mar 24 10:32:01 volumio volumio[26155]: Error adding Membership: Error: addMembership EINVAL Mar 24 10:32:01 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 24 10:32:01 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Mar 24 10:32:01 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:32:01 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 24 10:32:01 volumio sudo[26379]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio sudo[26374]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio volumio[26155]: info: Shairport-Sync Started Mar 24 10:32:01 volumio volumio[26155]: info: Shairport-Sync Started Mar 24 10:32:01 volumio volumio[26155]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=info msg="zeroconf server listening on port 38613" Mar 24 10:32:01 volumio mpd[26333]: 2026-03-24T10:32:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 24 10:32:01 volumio systemd[1]: Started mpd.service - Music Player Daemon. Mar 24 10:32:01 volumio sudo[26305]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio sudo[26297]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:01 volumio volumio[26155]: info: Completed starting Core Plugins Mar 24 10:32:01 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:32:01 volumio volumio[26155]: info: ----- MyVolumio plugins startup ---- Mar 24 10:32:01 volumio volumio[26155]: info: ------------------------------------------- Mar 24 10:32:01 volumio volumio[26155]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 24 10:32:01 volumio volumio[26155]: error: MPD error: The expression evaluated to a falsy value: Mar 24 10:32:01 volumio volumio[26155]: assert.ok(self.idling) Mar 24 10:32:01 volumio volumio[26155]: error: The expression evaluated to a falsy value: Mar 24 10:32:01 volumio volumio[26155]: assert.ok(self.idling) Mar 24 10:32:01 volumio volumio[26155]: info: MPD running with PID26333 Mar 24 10:32:01 volumio volumio[26155]: ,establishing connection Mar 24 10:32:01 volumio volumio[26155]: error: updateQueue error: null Mar 24 10:32:01 volumio volumio[26155]: error: updateQueue error: null Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=debug msg="obtained new client token: AADW92Wvpc8D8M6If3tqHdl1SPaq0irxgm3rdsBl8NOLOvWjGWid7RvvrpSGbz7yXh18UwWXqjGBndaYU/rgyTIgQdK2j8fu2JWuAfDNd9ikHhf5P+7YyAz53IwiGcpOoXBn133LI7O8dNSWXA9c9hpgrqNXC2LRHorNhIPPSvaZVb0jdo6f5IIhBcTaalpyYTjYWoIwvd7OoHc0Q4BMGnh8yFLtS46NkPhip8jdNe94uflN7GcQ3n0zOQ==" Mar 24 10:32:01 volumio go-librespot[26367]: time="2026-03-24T10:32:01Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="completed keyexchange" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="completed challenge" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:02 volumio volumio-remote-updater[945]: [2026-03-24 10:32:02] [connect] Successful connection Mar 24 10:32:02 volumio volumio-remote-updater[945]: [2026-03-24 10:32:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774348322 101 Mar 24 10:32:02 volumio volumio[26155]: 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: 2 Mar 24 10:32:02 volumio sudo[26196]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="completed keyexchange" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=debug msg="completed challenge" Mar 24 10:32:02 volumio go-librespot[26367]: time="2026-03-24T10:32:02Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:03 volumio go-librespot[26367]: time="2026-03-24T10:32:03Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:32:03 volumio go-librespot[26367]: time="2026-03-24T10:32:03Z" level=debug msg="completed keyexchange" Mar 24 10:32:03 volumio go-librespot[26367]: time="2026-03-24T10:32:03Z" level=debug msg="completed challenge" Mar 24 10:32:03 volumio go-librespot[26367]: time="2026-03-24T10:32:03Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:04 volumio volumio[26155]: info: go-librespot daemon successfully initialized Mar 24 10:32:04 volumio go-librespot[26367]: time="2026-03-24T10:32:04Z" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Mar 24 10:32:04 volumio go-librespot[26367]: time="2026-03-24T10:32:04Z" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 24 10:32:04 volumio go-librespot[26367]: time="2026-03-24T10:32:04Z" level=debug msg="completed keyexchange" Mar 24 10:32:04 volumio go-librespot[26367]: time="2026-03-24T10:32:04Z" level=debug msg="completed challenge" Mar 24 10:32:05 volumio go-librespot[26367]: time="2026-03-24T10:32:05Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:05 volumio go-librespot[26367]: time="2026-03-24T10:32:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:32:05 volumio go-librespot[26367]: time="2026-03-24T10:32:05Z" level=debug msg="completed keyexchange" Mar 24 10:32:05 volumio go-librespot[26367]: time="2026-03-24T10:32:05Z" level=debug msg="completed challenge" Mar 24 10:32:05 volumio go-librespot[26367]: time="2026-03-24T10:32:05Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:06 volumio go-librespot[26367]: time="2026-03-24T10:32:06Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:32:06 volumio go-librespot[26367]: time="2026-03-24T10:32:06Z" level=debug msg="completed keyexchange" Mar 24 10:32:06 volumio go-librespot[26367]: time="2026-03-24T10:32:06Z" level=debug msg="completed challenge" Mar 24 10:32:06 volumio go-librespot[26367]: time="2026-03-24T10:32:06Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:06 volumio go-librespot[26367]: time="2026-03-24T10:32:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:32:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:32:07 volumio volumio[26155]: info: Initializing connection to go-librespot Websocket Mar 24 10:32:07 volumio volumio[26155]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 24 10:32:08 volumio sudo[26429]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 24 10:32:08 volumio sudo[26429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:08 volumio sudo[26431]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 24 10:32:08 volumio sudo[26431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:08 volumio sudo[26429]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:08 volumio sudo[26431]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:08 volumio sudo[26433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 24 10:32:08 volumio sudo[26433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:08 volumio sudo[26433]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:08 volumio volumio[26155]: info: Upmpdcli Daemon Started Mar 24 10:32:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 24 10:32:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 24 10:32:09 volumio go-librespot[26437]: go-librespot daemon starting... Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=info msg="running go-librespot 0.6.2" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="app state loaded" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=info msg="api server listening on 127.0.0.1:9879" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=info msg="zeroconf server listening on port 34743" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="obtained new client token: AADLLY8GYQSdNHNYlcjK1gSPu5Ge/gDc7cVvbg2QYYp1OBqwO+t/jUxW9J/YFMExYsLio6/odBqlyUgdHsyBoxnKpbMHYNNkNiHwaiqwzOOqSbnAjH9ZtJFN4AQP3Uvh/S2wisr44GCIw+Id8NghJcpj9Wo73RWzZLnnaA1rY2a6ocPTm7roa3gsMROvXaoK6AfXU/0gNx42oEgOQXK95MMz/Wd14KJlEbtQNLpsQpmYq+8sOECY7Wdvfw==" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="completed keyexchange" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=debug msg="completed challenge" Mar 24 10:32:09 volumio go-librespot[26438]: time="2026-03-24T10:32:09Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin bluetooth to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin multiroom to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin metavolumio to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin cd_controller to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 24 10:32:09 volumio volumio[26155]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 24 10:32:10 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:10 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:10 volumio volumio[26155]: info: Starting MyVolumio Remote Streaming Endpoints Mar 24 10:32:10 volumio volumio[26155]: info: MyVolumio login type: Token Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="completed keyexchange" Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="completed challenge" Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 24 10:32:10 volumio volumio[26155]: info: Streaming services startup Mar 24 10:32:10 volumio volumio[26155]: info: Starting Streaming Daemon Mar 24 10:32:10 volumio sudo[26448]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:32:10 volumio volumio[26155]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 24 10:32:10 volumio sudo[26448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:10 volumio sudo[26448]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:10 volumio volumio[26155]: info: Initializing connection to go-librespot Websocket Mar 24 10:32:10 volumio volumio[26155]: error: Cannot start Volumio Streaming Daemon Mar 24 10:32:10 volumio volumio[26155]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:32:10 volumio volumio[26155]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="new websocket client" Mar 24 10:32:10 volumio volumio[26155]: info: Connection to go-librespot Websocket established Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="completed keyexchange" Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=debug msg="completed challenge" Mar 24 10:32:10 volumio volumio[26155]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Mar 24 10:32:10 volumio go-librespot[26438]: time="2026-03-24T10:32:10Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:11 volumio volumio[26155]: info: MyVolumio token set successfully Mar 24 10:32:11 volumio volumio[26155]: info: MYVOLUMIO: Adding device Mar 24 10:32:11 volumio volumio[26155]: info: MYVOLUMIO: Evaluating Server Mar 24 10:32:11 volumio volumio[26155]: info: MyVolumio status changed Mar 24 10:32:11 volumio volumio[26155]: info: Streaming services startup Mar 24 10:32:11 volumio volumio[26155]: info: Starting Streaming Daemon Mar 24 10:32:11 volumio volumio[26155]: info: Removing browser output: myVolumio user plan is not superstar Mar 24 10:32:11 volumio volumio[26155]: info: Removing audio output: Mar 24 10:32:11 volumio volumio[26155]: info: Stoppping Tunnel 1 Mar 24 10:32:11 volumio sudo[26476]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 24 10:32:11 volumio sudo[26476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:11 volumio sudo[26478]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Mar 24 10:32:11 volumio sudo[26478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 24 10:32:11 volumio sudo[26476]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:11 volumio volumio[26155]: error: Cannot start Volumio Streaming Daemon Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio volumio[26155]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Mar 24 10:32:11 volumio volumio[26155]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Mar 24 10:32:11 volumio sudo[26478]: pam_unix(sudo:session): session closed for user root Mar 24 10:32:11 volumio volumio[26155]: info: Remote SSH Stopped Mar 24 10:32:11 volumio go-librespot[26438]: time="2026-03-24T10:32:11Z" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 24 10:32:11 volumio go-librespot[26438]: time="2026-03-24T10:32:11Z" level=debug msg="completed keyexchange" Mar 24 10:32:11 volumio go-librespot[26438]: time="2026-03-24T10:32:11Z" level=debug msg="completed challenge" Mar 24 10:32:11 volumio volumio[26155]: info: Setting Geolocation for MyVolumio to eu3 Mar 24 10:32:11 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:11 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:11 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:11 volumio go-librespot[26438]: time="2026-03-24T10:32:11Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:11 volumio volumio[26155]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Mar 24 10:32:12 volumio volumio[26155]: info: Updating MyVolumio device info Mar 24 10:32:12 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:12 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:12 volumio volumio[26155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 24 10:32:12 volumio volumio[26155]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Mar 24 10:32:13 volumio go-librespot[26438]: time="2026-03-24T10:32:13Z" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 24 10:32:13 volumio go-librespot[26438]: time="2026-03-24T10:32:13Z" level=debug msg="completed keyexchange" Mar 24 10:32:13 volumio go-librespot[26438]: time="2026-03-24T10:32:13Z" level=debug msg="completed challenge" Mar 24 10:32:13 volumio volumio[26155]: info: Getting Spotify volume Mar 24 10:32:13 volumio volumio[26155]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 24 10:32:13 volumio volumio[26155]: info: CoreCommandRouter::volumioGetState Mar 24 10:32:13 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:13 volumio volumio[26155]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Mar 24 10:32:13 volumio volumio[26155]: SPOTIFY: SPOTIFY VOLUME undefined Mar 24 10:32:13 volumio volumio[26155]: SPOTIFY: VOLUMIO VOLUME 0 Mar 24 10:32:13 volumio volumio[26155]: info: Aligning Spotify Volume to Volumio Volume Mar 24 10:32:13 volumio volumio[26155]: info: CoreCommandRouter::volumioGetState Mar 24 10:32:13 volumio volumio[26155]: info: CorePlayQueue::getTrack 0 Mar 24 10:32:13 volumio volumio[26155]: info: Setting Spotify Volume from Volumio: 0 Mar 24 10:32:13 volumio go-librespot[26438]: time="2026-03-24T10:32:13Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:14 volumio go-librespot[26438]: time="2026-03-24T10:32:14Z" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 24 10:32:14 volumio go-librespot[26438]: time="2026-03-24T10:32:14Z" level=debug msg="completed keyexchange" Mar 24 10:32:14 volumio go-librespot[26438]: time="2026-03-24T10:32:14Z" level=debug msg="completed challenge" Mar 24 10:32:14 volumio go-librespot[26438]: time="2026-03-24T10:32:14Z" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:14 volumio go-librespot[26438]: time="2026-03-24T10:32:14Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 24 10:32:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 24 10:32:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 24 10:32:14 volumio volumio[26155]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:32:14 volumio volumio[26155]: Error: socket hang up Mar 24 10:32:14 volumio volumio[26155]: at connResetException (node:internal/errors:720:14) Mar 24 10:32:14 volumio volumio[26155]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 24 10:32:14 volumio volumio[26155]: at Socket.emit (node:events:526:35) Mar 24 10:32:14 volumio volumio[26155]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 24 10:32:14 volumio volumio[26155]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 24 10:32:14 volumio volumio[26155]: code: 'ECONNRESET', Mar 24 10:32:14 volumio volumio[26155]: response: undefined Mar 24 10:32:14 volumio volumio[26155]: } Mar 24 10:32:14 volumio volumio[26155]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 24 10:32:14 volumio sudo[26495]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-24 10:31' Mar 24 10:32:14 volumio sudo[26495]: 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"