Jan 13 20:24:31 volumio-v1 ntpd[1126]: CLOCK: time stepped by 47007.009214 Jan 13 20:24:31 volumio-v1 ntpd[1126]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: A device disappeared from network Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: Device volumio-v1 disappeared from network Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: A device disappeared from network Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: adding 7ccb273b-fb56-4f45-a1a0-98a522a29f84 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: Found device Volumio-v1 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:31 volumio-v1 volumio[1449]: info: CorePlayQueue::getTrack 0 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: this is already registered, 7ccb273b-fb56-4f45-a1a0-98a522a29f84 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: Discovery: Found device Volumio-v1 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:31 volumio-v1 volumio[1449]: info: CorePlayQueue::getTrack 0 Jan 13 20:24:31 volumio-v1 volumio[1449]: info: go-librespot daemon successfully initialized Jan 13 20:24:31 volumio-v1 volumio[1449]: error: [yt-cast-receiver] RPC connection reader error: Jan 13 20:24:31 volumio-v1 volumio[1449]: (TypeError) terminated Jan 13 20:24:31 volumio-v1 volumio[1449]: TypeError: terminated Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.onAborted (node:internal/deps/undici/undici:11442:53) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.emit (node:events:514:28) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.terminate (node:internal/deps/undici/undici:10695:14) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Object.onError (node:internal/deps/undici/undici:11537:36) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Request.onError (node:internal/deps/undici/undici:8310:31) Jan 13 20:24:31 volumio-v1 volumio[1449]: at errorRequest (node:internal/deps/undici/undici:10378:17) Jan 13 20:24:31 volumio-v1 volumio[1449]: at TLSSocket.onSocketClose (node:internal/deps/undici/undici:9811:9) Jan 13 20:24:31 volumio-v1 volumio[1449]: at TLSSocket.emit (node:events:526:35) Jan 13 20:24:31 volumio-v1 volumio[1449]: at node:net:337:12 Jan 13 20:24:31 volumio-v1 volumio[1449]: at TCP.done (node:_tls_wrap:631:7) Jan 13 20:24:31 volumio-v1 volumio[1449]: error: [yt-cast-receiver] RPC connection reader error: Jan 13 20:24:31 volumio-v1 volumio[1449]: (TypeError) terminated Jan 13 20:24:31 volumio-v1 volumio[1449]: TypeError: terminated Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.onAborted (node:internal/deps/undici/undici:11442:53) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.emit (node:events:514:28) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Fetch.terminate (node:internal/deps/undici/undici:10695:14) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Object.onError (node:internal/deps/undici/undici:11537:36) Jan 13 20:24:31 volumio-v1 volumio[1449]: at Request.onError (node:internal/deps/undici/undici:8310:31) Jan 13 20:24:31 volumio-v1 volumio[1449]: at errorRequest (node:internal/deps/undici/undici:10378:17) Jan 13 20:24:31 volumio-v1 volumio[1449]: at TLSSocket.onSocketClose (node:internal/deps/undici/undici:9811:9) Jan 13 20:24:31 volumio-v1 volumio[1449]: at TLSSocket.emit (node:events:526:35) Jan 13 20:24:31 volumio-v1 volumio[1449]: at node:net:337:12 Jan 13 20:24:31 volumio-v1 volumio[1449]: at TCP.done (node:_tls_wrap:631:7) Jan 13 20:24:32 volumio-v1 volumio-remote-updater[929]: [2026-01-13 20:24:32] [connect] Successful connection Jan 13 20:24:32 volumio-v1 volumio-remote-updater[929]: [2026-01-13 20:24:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768332272 101 Jan 13 20:24:32 volumio-v1 volumio[1449]: 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: 3 Jan 13 20:24:32 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 13 20:24:32 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:32 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:32 volumio-v1 go-librespot[1735]: go-librespot daemon starting... Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=debug msg="app state loaded" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=info msg="zeroconf server listening on port 44791" Jan 13 20:24:32 volumio-v1 sudo[1744]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 13 20:24:32 volumio-v1 sudo[1744]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:32 volumio-v1 sudo[1746]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 13 20:24:32 volumio-v1 sudo[1746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:32 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:32+01:00" level=debug msg="obtained new client token: AAAh//CT3t44NtC0fsQ/woxWgj9YCWyNJcLGOwIbY6uQKGsit38INKpUjtGRRqwJOdUfgc1yP25ZmHR+CQs/9cMbxHiIqwixh5e9sMWz8cUOXTbx4KJ9Ozv98/XnazdU54UGVoa3KnUq7oSZXGYz7hLrgFMZHWeBg3pWVBwFxp9+RYMewNgiBZoF2lgVvwD+qeViuZV8f3xSZiEZLxnwbIWhMIQnka9ozm+GP/3a++2iZ2jclvefH5/6hQ==" Jan 13 20:24:33 volumio-v1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 13 20:24:33 volumio-v1 mpd_monitor.sh[1749]: MPD Monitor Service: Starting MPD Monitor Service Jan 13 20:24:33 volumio-v1 sudo[1746]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:33 volumio-v1 sudo[1744]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:33 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:24:33 volumio-v1 volumio[1449]: info: Successfully started MPD Monitor Jan 13 20:24:33 volumio-v1 volumio[1449]: info: Successfully started MPD Monitor Jan 13 20:24:33 volumio-v1 go-librespot[1736]: time="2026-01-13T20:24:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:33 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:33 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:34 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:34 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:34 volumio-v1 volumio[1449]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 13 20:24:36 volumio-v1 sudo[1769]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 13 20:24:36 volumio-v1 sudo[1769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:36 volumio-v1 sudo[1771]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 13 20:24:36 volumio-v1 sudo[1771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:36 volumio-v1 sudo[1769]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:36 volumio-v1 sudo[1771]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:36 volumio-v1 sudo[1775]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 13 20:24:36 volumio-v1 sudo[1775]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:36 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 13 20:24:36 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:36 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:36 volumio-v1 go-librespot[1777]: go-librespot daemon starting... Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="app state loaded" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=info msg="zeroconf server listening on port 36265" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="obtained new client token: AAA/sgxkX/ImhM4YvsPGi7qhaw/t929Kk5F3ZoJ/+FlugKmX8jHIU/9T6yOo0VlhdF5wioPcybINmzzwNkx34tS1E8tltY0ofgP7ZIEpV8888vaYg2rznMjfisGj2ePGTJhEoR8WMKtkhuCCUQ/uB4rqJFYdhgl3lf2+L088lh75OIg1zFVwAX1UkmTDT0rWASHiVdQiSWJHjYB4p5fzGI12izp59sSaGT3mGZppOua5y312Je0iHHPBpQ==" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:24:36 volumio-v1 go-librespot[1778]: time="2026-01-13T20:24:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:36 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:36 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:37 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:37 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:38 volumio-v1 systemd[1]: systemd-fsckd.service: Deactivated successfully. Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin bluetooth to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin multiroom to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin metavolumio to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin cd_controller to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 13 20:24:38 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:38 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:38 volumio-v1 volumio[1449]: info: Starting MyVolumio Remote Streaming Endpoints Jan 13 20:24:38 volumio-v1 volumio[1449]: info: MyVolumio login type: Token Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 13 20:24:38 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 13 20:24:39 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 13 20:24:39 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 13 20:24:39 volumio-v1 volumio[1449]: info: Streaming services startup Jan 13 20:24:39 volumio-v1 volumio[1449]: info: Starting Streaming Daemon Jan 13 20:24:39 volumio-v1 sudo[1786]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 13 20:24:39 volumio-v1 sudo[1786]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:39 volumio-v1 sudo[1786]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:39 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 13 20:24:39 volumio-v1 volumio[1449]: error: Cannot start Volumio Streaming Daemon Jan 13 20:24:39 volumio-v1 volumio[1449]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 13 20:24:39 volumio-v1 volumio[1449]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 13 20:24:39 volumio-v1 dhcpcd[911]: timed out Jan 13 20:24:39 volumio-v1 sh[896]: timed out Jan 13 20:24:39 volumio-v1 dhcpcd[911]: dhcpcd exited Jan 13 20:24:39 volumio-v1 sh[829]: ifup: failed to bring up eth0 Jan 13 20:24:39 volumio-v1 systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:39 volumio-v1 systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Jan 13 20:24:39 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 13 20:24:39 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:39 volumio-v1 volumio[1449]: error: MyVolumio Custom Token format not valid, refreshing it Jan 13 20:24:39 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:39 volumio-v1 go-librespot[1794]: go-librespot daemon starting... Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="app state loaded" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=info msg="zeroconf server listening on port 39723" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="obtained new client token: AADmDzE/IZeOk0/9beLX6/qhk08tt2a4D9GrTZPXce/5NexW24/xp16sRP/Fz/3iPdFZax+oLqtsxzYWt4kpw66Gp3EtbE7cx8Byz5EsgBpDdCS5EteMBnPlE2tTLdniRRjEQ1B6f3bhXKnGNpy5+wq4rXxJsJz+1sT5+Qx6d9fDx4qHMzaa58fFH85pSEe6zeNOXf89vCbhjjDPknEX0LMTZYrA+zFq7qOHLfhoVdp2r9SN3TAFg5ilUg==" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:24:39 volumio-v1 go-librespot[1795]: time="2026-01-13T20:24:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:39 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:39 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:39 volumio-v1 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MyVolumio login type: Token Jan 13 20:24:40 volumio-v1 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Jan 13 20:24:40 volumio-v1 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Jan 13 20:24:40 volumio-v1 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Jan 13 20:24:40 volumio-v1 sudo[1775]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Upmpdcli Daemon Started Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MyVolumio token set successfully Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MYVOLUMIO: Adding device Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MYVOLUMIO: Evaluating Server Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MyVolumio Plan changed: premium Jan 13 20:24:40 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Removing browser output: myVolumio user plan is not superstar Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Removing audio output: Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MYVOLUMIO: Adding device Jan 13 20:24:40 volumio-v1 volumio[1449]: info: MYVOLUMIO: Evaluating Server Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Remote config written successfully Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Starting Tunnel 1 Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Starting Tunnel Connection Checker Jan 13 20:24:40 volumio-v1 volumio[1449]: info: Completed starting MyVolumio Plugin Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MYVolumio Device enabled Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MyVolumio status changed Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Streaming services startup Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Starting Streaming Daemon Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Jan 13 20:24:41 volumio-v1 sudo[1862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 13 20:24:41 volumio-v1 sudo[1862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1862]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Jan 13 20:24:41 volumio-v1 sudo[1866]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Jan 13 20:24:41 volumio-v1 sudo[1866]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1866]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: MultiRoom plugin initialized Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: STOPPING SNAPCLIENT Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Snap server stop Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: STOPPING volumioStreaming Jan 13 20:24:41 volumio-v1 sudo[1884]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Jan 13 20:24:41 volumio-v1 sudo[1884]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Jan 13 20:24:41 volumio-v1 sudo[1885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1887]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jan 13 20:24:41 volumio-v1 sudo[1887]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Jan 13 20:24:41 volumio-v1 sudo[1890]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jan 13 20:24:41 volumio-v1 sudo[1890]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Jan 13 20:24:41 volumio-v1 sudo[1890]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Jan 13 20:24:41 volumio-v1 sudo[1884]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Jan 13 20:24:41 volumio-v1 sudo[1887]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 sudo[1885]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Preparing to generate the ALSA configuration file Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Setting Geolocation for MyVolumio to eu5 Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Reading ALSA contributions from plugins. Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Setting Geolocation for MyVolumio to eu9 Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Removed streaming files Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: volumioStreaming STOPPED Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: SNAPSERVER STOPPED Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: SNAPCLIENT STOPPED Jan 13 20:24:41 volumio-v1 volumio[1449]: error: Cannot start Volumio Streaming Daemon Jan 13 20:24:41 volumio-v1 volumio[1449]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 13 20:24:41 volumio-v1 volumio[1449]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Asound.conf file written Jan 13 20:24:41 volumio-v1 sudo[1896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Jan 13 20:24:41 volumio-v1 sudo[1896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1896]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Jan 13 20:24:41 volumio-v1 volumio[1449]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Jan 13 20:24:41 volumio-v1 volumio[1449]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Output device has changed, restarting MPD Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Output device has changed, restarting Shairport Sync Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:41 volumio-v1 sudo[1903]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 13 20:24:41 volumio-v1 sudo[1903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 sudo[1903]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:41 volumio-v1 sudo[1905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 13 20:24:41 volumio-v1 sudo[1905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: [FUNC] onStart Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Jan 13 20:24:41 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output for this device Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:41 volumio-v1 systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding audio output: Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding audio output: Jan 13 20:24:41 volumio-v1 volumio[1449]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding METAVOLUMIO REST API Endpoints Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Jan 13 20:24:41 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Preparing CD Folders Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding CD REST API Endpoints Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Starting UDEV Watcher for CD Jan 13 20:24:41 volumio-v1 volumio[1449]: info: Detecting CD presence with UDEV Jan 13 20:24:41 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Jan 13 20:24:41 volumio-v1 bluetoothd[921]: Path / reserved for Adv Monitor app :1.24 Jan 13 20:24:41 volumio-v1 bluetoothd[921]: Adv Monitor app :1.24 disconnected from D-Bus Jan 13 20:24:41 volumio-v1 systemd[1]: mpd.service: Deactivated successfully. Jan 13 20:24:41 volumio-v1 systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 13 20:24:41 volumio-v1 systemd[1]: mpd.service: Consumed 1.169s CPU time. Jan 13 20:24:41 volumio-v1 systemd[1]: mpd.socket: Deactivated successfully. Jan 13 20:24:41 volumio-v1 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 13 20:24:41 volumio-v1 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 13 20:24:41 volumio-v1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 13 20:24:41 volumio-v1 systemd[1]: Starting mpd.service - Music Player Daemon... Jan 13 20:24:42 volumio-v1 sudo[1924]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 13 20:24:42 volumio-v1 sudo[1924]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 13 20:24:42 volumio-v1 sudo[1924]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:42 volumio-v1 mpd[1926]: 2026-01-13T20:24:42 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 13 20:24:42 volumio-v1 systemd[1]: Started mpd.service - Music Player Daemon. Jan 13 20:24:42 volumio-v1 sudo[1905]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:42 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jan 13 20:24:42 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:42 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:42 volumio-v1 go-librespot[1929]: go-librespot daemon starting... Jan 13 20:24:42 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:42+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:42 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:42+01:00" level=debug msg="app state loaded" Jan 13 20:24:42 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:42+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=info msg="zeroconf server listening on port 38297" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=debug msg="obtained new client token: AACE85ZwDg8WpJOaX7nrhqBv+px9VFrnYgNZZXuuwZ9+cOcbo/jv8o3Vz3PcUb4uPOQphiwKLIL+k8juMIT8A5fBbZqcKlE26iO9w9S0CnvD3hGRYT5LOlgHULiGJ6QrZsv50oh8jNTA3eU7YEFwqc+KwXu7fYhnVffdy5+Lq4uQvFLD81wfkyDLBcXyZUqHrJbCGxnS7DgipNQTL0vUaco3lOjhFY0YqYCC0/A0VP7OEGirfydR4kw=" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:24:43 volumio-v1 go-librespot[1930]: time="2026-01-13T20:24:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.86.250:50282->34.158.1.133:4070: read: connection reset by peer" Jan 13 20:24:43 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:43 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:46 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 13 20:24:46 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:46 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:46 volumio-v1 go-librespot[1951]: go-librespot daemon starting... Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="app state loaded" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=info msg="zeroconf server listening on port 36445" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="obtained new client token: AACpEgSyphyluls9xa0jhThiK69WZ4QYu/zv2FjNlL44JsPScNwoSIx71bPM6Guxpuhy1i8XCWuqUFec8Gv6IHLEA3Pmp0QcBUKEj7wLbxkzaxb5g25BmzX6BBJxfvJ1UNc1X0R55Ax5WqSMHjX5gtKl4qPoU9iSVwJ6mlmNDTmvgZ4E/MWRzjjQV836ZqTwe9Cr2MUv1BSDweNPtoJ0aOSBfBahquFuqLoQKz3LSJ1kTzO4K8Gg/fW/AA==" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jan 13 20:24:46 volumio-v1 go-librespot[1952]: time="2026-01-13T20:24:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:46 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:46 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:46 volumio-v1 volumio[1449]: warn: [cd-plugin] cdspeedctl: device or media not ready Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding inputs REST Endpoints Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Scanning Audio Inputs Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Checking against Known Cards name Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding Server instance for streaming Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Jan 13 20:24:46 volumio-v1 volumio[1449]: error: Hi Res Audio Failed Login: Missing Login Data Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding HIGHRESAUDIO REST API Endpoints Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Refreshing QOBUZ token Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Jan 13 20:24:46 volumio-v1 volumio[1449]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Jan 13 20:24:46 volumio-v1 sudo[1963]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Jan 13 20:24:46 volumio-v1 sudo[1963]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:46 volumio-v1 volumio[1449]: info: QobuzConnect: Starting Qobuz Connect socket and service Jan 13 20:24:46 volumio-v1 volumio[1449]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Adding TIDAL REST API Endpoints Jan 13 20:24:46 volumio-v1 sudo[1970]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Jan 13 20:24:46 volumio-v1 sudo[1970]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Updating MyVolumio device info Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Updating MyVolumio device info Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 sudo[1970]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:46 volumio-v1 volumio[1449]: info: MRS: Getting audio outputs on start Jan 13 20:24:46 volumio-v1 volumio[1449]: info: MRS: Requesting all other devices output Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:46 volumio-v1 sudo[1972]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Jan 13 20:24:46 volumio-v1 sudo[1972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:46 volumio-v1 sudo[1963]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Successfully Added MyVolumio device Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Successfully Added MyVolumio device Jan 13 20:24:46 volumio-v1 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Jan 13 20:24:46 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Jan 13 20:24:46 volumio-v1 sudo[1972]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:46 volumio-v1 volumio[1449]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Jan 13 20:24:46 volumio-v1 volumio[1449]: info: MPD Permissions set Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CorePlayQueue::getTrack 0 Jan 13 20:24:46 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:46 volumio-v1 sudo[1977]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Jan 13 20:24:46 volumio-v1 sudo[1977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:46 volumio-v1 systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Jan 13 20:24:46 volumio-v1 sudo[1977]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:46 volumio-v1 volumio[1449]: error: updateQueue error: null Jan 13 20:24:46 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioStop Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreStateMachine::stop Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 13 20:24:46 volumio-v1 volumio[1449]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Jan 13 20:24:46 volumio-v1 volumio[1449]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 13 20:24:46 volumio-v1 volumiobt[1991]: INFO [BTSTART] Ensuring Bluetooth directory exists... Jan 13 20:24:46 volumio-v1 sudo[1992]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Jan 13 20:24:46 volumio-v1 sudo[1992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:46 volumio-v1 sudo[1992]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 sudo[1994]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Jan 13 20:24:47 volumio-v1 sudo[1994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 sudo[1994]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumiobt[1996]: INFO [BTSTART] Powering on Bluetooth if needed... Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Executing endpoint qc_getconfig Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Jan 13 20:24:47 volumio-v1 bluetoothd[921]: Adv Monitor app :1.25 disconnected from D-Bus Jan 13 20:24:47 volumio-v1 volumiobt[2002]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.024 [1975.1975] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Starting Shairport Sync Jan 13 20:24:47 volumio-v1 sudo[2006]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 13 20:24:47 volumio-v1 sudo[2006]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Jan 13 20:24:47 volumio-v1 volumio[1449]: info: QobuzConnect: QOBUZ Connect daemon connected Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Preparing to generate the ALSA configuration file Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 13 20:24:47 volumio-v1 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 systemd[1]: shairport-sync.service: Consumed 1.532s CPU time. Jan 13 20:24:47 volumio-v1 sudo[2009]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Jan 13 20:24:47 volumio-v1 sudo[2009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Reading ALSA contributions from plugins. Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [176B blob data] Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [157B blob data] Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [157B blob data] Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [157B blob data] Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [113B blob data] Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [bluetoothctl]> discoverable on Jan 13 20:24:47 volumio-v1 volumiobt[2003]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [bluetoothctl]> pairable on Jan 13 20:24:47 volumio-v1 bluetoothd[921]: Adv Monitor app :1.27 disconnected from D-Bus Jan 13 20:24:47 volumio-v1 volumiobt[2003]: [bluetoothctl]> Jan 13 20:24:47 volumio-v1 volumiobt[2012]: INFO [BTSTART] Registering Bluetooth agent... Jan 13 20:24:47 volumio-v1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 sudo[2006]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.075 [1975.1975] INFO VolumeManager: [0xdc4228]: Setting new playback volume: 75 Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.075 [1975.1975] INFO VolumeManager: [0xdc4228]: Setting new mute state: 0 Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.075 [1975.1975] INFO QobuzConnect: [0xdc4bf8]: Client initialized! Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.075 [1975.1975] INFO SampleApp: Starting Avahi advertising, name: Volumio-v1, service name: _qobuz-connect._tcp Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Shairport-Sync Started Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.082 [1975.1975] INFO LocalConfigManager: [0xdc3b08]: Starting Local Configuration server Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.082 [1975.1975] INFO SampleApp: Starting Local configuration server Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.082 [1975.1975] INFO SampleApp: Connected to UNIX socket client 0xdae818 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Access Token successfully retrieved Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 13 20:24:47 volumio-v1 volumio[1449]: info: [1768332287089] CoreMusicLibrary::Adding element QOBUZ Jan 13 20:24:47 volumio-v1 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. Jan 13 20:24:47 volumio-v1 volumiobt[2013]: [NEW] Media /org/bluez/hci0 Jan 13 20:24:47 volumio-v1 volumiobt[2013]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 volumiobt[2013]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 volumiobt[2013]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 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. Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 13 20:24:47 volumio-v1 volumio[1449]: Cannot find translation for source Spotify Jan 13 20:24:47 volumio-v1 volumio[1449]: Cannot find translation for source QOBUZ Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Stopping AccessToken refresher cron for QOBUZ Jan 13 20:24:47 volumio-v1 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Jan 13 20:24:47 volumio-v1 bluetoothd[921]: Adv Monitor app :1.29 disconnected from D-Bus Jan 13 20:24:47 volumio-v1 autossh[2030]: port set to 0, monitoring disabled Jan 13 20:24:47 volumio-v1 autossh[2030]: starting ssh (count 1) Jan 13 20:24:47 volumio-v1 autossh[2030]: ssh child pid is 2035 Jan 13 20:24:47 volumio-v1 sudo[2009]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumiobt[2034]: No agent is registered Jan 13 20:24:47 volumio-v1 volumiobt[2034]: [NEW] Media /org/bluez/hci0 Jan 13 20:24:47 volumio-v1 volumiobt[2034]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 volumiobt[2034]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 volumiobt[2034]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Jan 13 20:24:47 volumio-v1 bluetoothd[921]: Adv Monitor app :1.32 disconnected from D-Bus Jan 13 20:24:47 volumio-v1 volumiobt[2036]: INFO [BTSTART] Agent registered successfully. Jan 13 20:24:47 volumio-v1 volumiobt[2037]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Jan 13 20:24:47 volumio-v1 volumio[1449]: info: AccessToken refresher cron started for QOBUZ Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Adding QOBUZ REST API Endpoints Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Found cast device: Chromecast-943f7995fa4c83630684a5e96c8101d7 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Adding audio output: Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Remote SSH Started Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.173 [1975.1975] INFO SampleApp: Playback volume changed: 75 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 volumio[1449]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Asound.conf file unchanged, so no further update is needed Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Output device has changed, restarting MPD Jan 13 20:24:47 volumio-v1 sudo[2040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 13 20:24:47 volumio-v1 sudo[2040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Output device has changed, restarting Shairport Sync Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:47 volumio-v1 sudo[2040]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 sudo[2044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 13 20:24:47 volumio-v1 sudo[2044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: QobuzConnect: setDeactiveState invoked Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 systemd[1]: mpd.service: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 13 20:24:47 volumio-v1 systemd[1]: mpd.socket: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 13 20:24:47 volumio-v1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 13 20:24:47 volumio-v1 systemd[1]: Starting mpd.service - Music Player Daemon... Jan 13 20:24:47 volumio-v1 volumiossh-tunnel[2035]: Warning: Permanently added '[eu9.myvolumio.org]:2222' (RSA) to the list of known hosts. Jan 13 20:24:47 volumio-v1 sudo[2058]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Jan 13 20:24:47 volumio-v1 sudo[2058]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Successfully Updated MyVolumio device Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Successfully Updated MyVolumio device Jan 13 20:24:47 volumio-v1 sudo[2058]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 sudo[2056]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 13 20:24:47 volumio-v1 sudo[2060]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Jan 13 20:24:47 volumio-v1 sudo[2060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 sudo[2056]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 13 20:24:47 volumio-v1 sudo[2056]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MPD Permissions set Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::servicePushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreStateMachine::pushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioPushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output update for this device Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::servicePushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreStateMachine::pushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioPushState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output update for this device Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Jan 13 20:24:47 volumio-v1 qobuz-connect[1975]: 20260113 20:24:47.445 [1975.1975] INFO SampleApp: Stopping Local configuration server Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.0ku4BSWBhGMr5XDXSei0zCUeGke2.0fe46fc4286bff1ecd7e8a16cd086327.state.track' Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Starting Shairport Sync Jan 13 20:24:47 volumio-v1 volumio[1449]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.0ku4BSWBhGMr5XDXSei0zCUeGke2.0fe46fc4286bff1ecd7e8a16cd086327.state.track' Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Preparing to generate the ALSA configuration file Jan 13 20:24:47 volumio-v1 volumio[1449]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Reading ALSA contributions from plugins. Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Asound.conf file unchanged, so no further update is needed Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Output device has changed, restarting MPD Jan 13 20:24:47 volumio-v1 sudo[2070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 13 20:24:47 volumio-v1 sudo[2070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Output device has changed, restarting Shairport Sync Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:47 volumio-v1 sudo[2072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 13 20:24:47 volumio-v1 sudo[2072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 sudo[2074]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 13 20:24:47 volumio-v1 sudo[2074]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 sudo[2072]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 13 20:24:47 volumio-v1 volumio[1449]: info: QobuzConnect: setDeactiveState invoked Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:47 volumio-v1 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 volumio[1449]: info: MPD Permissions set Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 sudo[2090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 sudo[2090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 systemd[1]: mpd.service: Deactivated successfully. Jan 13 20:24:47 volumio-v1 volumiobt[2038]: INFO:a2dp-agent:Connecting to system bus. Jan 13 20:24:47 volumio-v1 sudo[2070]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:47 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:47 volumio-v1 volumiobt[2038]: INFO:a2dp-agent:Found Bluetooth adapter at: /org/bluez/hci0 Jan 13 20:24:47 volumio-v1 volumiobt[2038]: INFO:a2dp-agent:Enabling infinite discovery on adapter. Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Shairport-Sync Started Jan 13 20:24:47 volumio-v1 systemd[1]: mpd.socket: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 13 20:24:47 volumio-v1 volumio[1449]: error: [ytcr] Error connecting MPD: Jan 13 20:24:47 volumio-v1 volumio[1449]: (Error) read ECONNRESET Jan 13 20:24:47 volumio-v1 volumio[1449]: Error: read ECONNRESET Jan 13 20:24:47 volumio-v1 volumio[1449]: at Pipe.onStreamRead (node:internal/stream_base_commons:217:20) Jan 13 20:24:47 volumio-v1 volumio[1449]: Retrying in 5 seconds... Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Starting Shairport Sync Jan 13 20:24:47 volumio-v1 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 13 20:24:47 volumio-v1 systemd[1]: Starting mpd.service - Music Player Daemon... Jan 13 20:24:47 volumio-v1 volumiobt[2038]: INFO:a2dp-agent:Registering agent. Jan 13 20:24:47 volumio-v1 sudo[2090]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumiobt[2038]: INFO:a2dp-agent:Searching for MediaPlayer1 interface... Jan 13 20:24:47 volumio-v1 volumiobt[2038]: WARNING:a2dp-agent:No active MediaPlayer1 found. Metadata updates won't work. Jan 13 20:24:47 volumio-v1 sudo[2113]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 13 20:24:47 volumio-v1 sudo[2113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 sudo[2114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Jan 13 20:24:47 volumio-v1 sudo[2114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:47 volumio-v1 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 13 20:24:47 volumio-v1 systemd[1]: shairport-sync.service: Deactivated successfully. Jan 13 20:24:47 volumio-v1 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 sudo[2110]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 13 20:24:47 volumio-v1 sudo[2110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 13 20:24:47 volumio-v1 sudo[2110]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 13 20:24:47 volumio-v1 sudo[2113]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:47 volumio-v1 volumio[1449]: info: Shairport-Sync Started Jan 13 20:24:48 volumio-v1 mpd[2120]: 2026-01-13T20:24:48 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 13 20:24:48 volumio-v1 systemd[1]: Started mpd.service - Music Player Daemon. Jan 13 20:24:48 volumio-v1 sudo[2044]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:48 volumio-v1 sudo[2074]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:48 volumio-v1 volumio[1449]: error: updateQueue error: null Jan 13 20:24:48 volumio-v1 volumio[1449]: error: updateQueue error: null Jan 13 20:24:48 volumio-v1 upmpdcli[2137]: writing RSA key Jan 13 20:24:49 volumio-v1 qobuz-connect[1975]: 20260113 20:24:49.087 [1975.1975] INFO SampleApp: shat down connection on UNIX socket Jan 13 20:24:49 volumio-v1 volumio[1449]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Jan 13 20:24:49 volumio-v1 volumio[1449]: info: QobuzConnect: setDeactiveState invoked Jan 13 20:24:49 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:49 volumio-v1 systemd[1]: qobuz-connect.service: Deactivated successfully. Jan 13 20:24:49 volumio-v1 systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Jan 13 20:24:49 volumio-v1 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Jan 13 20:24:49 volumio-v1 sudo[2114]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:49 volumio-v1 sudo[2060]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Executing endpoint qc_getconfig Jan 13 20:24:49 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.135 [2143.2143] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.137 [2143.2143] INFO VolumeManager: [0x1926228]: Setting new playback volume: 75 Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.137 [2143.2143] INFO VolumeManager: [0x1926228]: Setting new mute state: 0 Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.137 [2143.2143] INFO QobuzConnect: [0x1926bf8]: Client initialized! Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.137 [2143.2143] INFO SampleApp: Starting Avahi advertising, name: Volumio-v1, service name: _qobuz-connect._tcp Jan 13 20:24:49 volumio-v1 volumio[1449]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Jan 13 20:24:49 volumio-v1 volumio[1449]: info: QobuzConnect: QOBUZ Connect daemon connected Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.141 [2143.2143] INFO LocalConfigManager: [0x1925b08]: Starting Local Configuration server Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.141 [2143.2143] INFO SampleApp: Starting Local configuration server Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.141 [2143.2143] INFO SampleApp: Connected to UNIX socket client 0x1910818 Jan 13 20:24:49 volumio-v1 qobuz-connect[2143]: 20260113 20:24:49.285 [2143.2143] INFO SampleApp: Playback volume changed: 75 Jan 13 20:24:49 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:49 volumio-v1 volumio[1449]: info: TidalConnect service stoped! Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Jan 13 20:24:49 volumio-v1 sudo[2161]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Jan 13 20:24:49 volumio-v1 sudo[2161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:49 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 13 20:24:49 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:49 volumio-v1 sudo[2165]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 13 20:24:49 volumio-v1 sudo[2165]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:49 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:49 volumio-v1 go-librespot[2163]: go-librespot daemon starting... Jan 13 20:24:49 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:49+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:49 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:49+01:00" level=debug msg="app state loaded" Jan 13 20:24:49 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:49 volumio-v1 systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jan 13 20:24:49 volumio-v1 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 13 20:24:49 volumio-v1 sudo[2161]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:49 volumio-v1 systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 13 20:24:49 volumio-v1 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 13 20:24:49 volumio-v1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 13 20:24:49 volumio-v1 mpd_monitor.sh[2176]: MPD Monitor Service: Starting MPD Monitor Service Jan 13 20:24:49 volumio-v1 sudo[2165]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:49 volumio-v1 volumio[1449]: info: Successfully started MPD Monitor Jan 13 20:24:50 volumio-v1 volumio[1449]: info: Executing endpoint tc_getconfig Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Jan 13 20:24:50 volumio-v1 vtcs[2174]: STARTING TidalConnect services, version: 1.5.2.56 Jan 13 20:24:50 volumio-v1 vtcs[2174]: STARTED TidalConnect services. Jan 13 20:24:50 volumio-v1 volumio[1449]: info: Executing endpoint tc_connect Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Jan 13 20:24:50 volumio-v1 volumio[1449]: info: Connecting to TidalConnect Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::servicePushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreStateMachine::pushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioPushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output update for this device Jan 13 20:24:50 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CorePlayQueue::getTrack 0 Jan 13 20:24:50 volumio-v1 volumio[1449]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received tidalconnect Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::servicePushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreStateMachine::pushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioPushState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output update for this device Jan 13 20:24:50 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:50 volumio-v1 volumio[1449]: info: CorePlayQueue::getTrack 0 Jan 13 20:24:50 volumio-v1 volumio[1449]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current qobuz Received tidalconnect Jan 13 20:24:50 volumio-v1 volumio[1449]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.0ku4BSWBhGMr5XDXSei0zCUeGke2.0fe46fc4286bff1ecd7e8a16cd086327.state.track' Jan 13 20:24:50 volumio-v1 volumio[1449]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.0ku4BSWBhGMr5XDXSei0zCUeGke2.0fe46fc4286bff1ecd7e8a16cd086327.state.track' Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=info msg="zeroconf server listening on port 37723" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=debug msg="obtained new client token: AADRdJdeC/JnHMq/k+vB+ij1fJp8zJa4fJah/YanoZDyAZ0/Xqcz4PXUE0KGjG38iQsb1G5bfcEf6ZL8c4YjG0QMwwXs4SnBWfHkOiMSrQi3wh9naI/BgQn41OyUyPq9H0OGWO3ivFji4Buv7QYaIsDOSTRJC+1TrmW92n1vS2TAITfD1k4pzqvIQkKYXq4vLGmUCWvPrmJFZm/XsLBEbnTNKFHU719CVPzV1AC54pVh29EZY5/qDk8=" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:24:50 volumio-v1 go-librespot[2167]: time="2026-01-13T20:24:50+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:50 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:50 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:51 volumio-v1 sudo[2197]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 13 20:24:51 volumio-v1 sudo[2197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:51 volumio-v1 sudo[2199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 13 20:24:51 volumio-v1 sudo[2199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 13 20:24:51 volumio-v1 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 13 20:24:51 volumio-v1 systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 13 20:24:51 volumio-v1 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 13 20:24:51 volumio-v1 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 13 20:24:51 volumio-v1 mpd_monitor.sh[2202]: MPD Monitor Service: Starting MPD Monitor Service Jan 13 20:24:51 volumio-v1 sudo[2199]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:51 volumio-v1 sudo[2197]: pam_unix(sudo:session): session closed for user root Jan 13 20:24:51 volumio-v1 volumio[1449]: info: Successfully started MPD Monitor Jan 13 20:24:51 volumio-v1 volumio[1449]: info: Successfully started MPD Monitor Jan 13 20:24:52 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:52 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:52 volumio-v1 volumio[1449]: info: TidalConnect service started! Jan 13 20:24:52 volumio-v1 volumio[1449]: [Metrics] CommandRouter: 27s 727.10ms Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumiosetStartupVolume Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:52 volumio-v1 volumio[1449]: info: VolumeController:: Setting startup Volume 10 Jan 13 20:24:52 volumio-v1 volumio[1449]: info: VolumeController::SetAlsaVolume10 Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::Close All Modals sent Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::Close All Modals sent Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreStateMachine::pushState Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioPushState Jan 13 20:24:52 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output update for this device Jan 13 20:24:52 volumio-v1 volumio[1449]: info: MRS: Pushing multiroomSync output Jan 13 20:24:52 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:52 volumio-v1 volumio[1449]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.0ku4BSWBhGMr5XDXSei0zCUeGke2.0fe46fc4286bff1ecd7e8a16cd086327.state.track' Jan 13 20:24:53 volumio-v1 volumio[1449]: info: Bluetoothremote--- Checking for trusted devices to reconnect... Jan 13 20:24:53 volumio-v1 volumio[1449]: info: Bluetoothremote--- Device list cleared and placeholder written. Jan 13 20:24:53 volumio-v1 bluetoothd[921]: Adv Monitor app :1.41 disconnected from D-Bus Jan 13 20:24:53 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 13 20:24:53 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:53 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:53 volumio-v1 go-librespot[2211]: go-librespot daemon starting... Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=debug msg="app state loaded" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 13 20:24:53 volumio-v1 volumio[1449]: info: Bluetoothremote--- Device found: Press scan to detect BT device - xx Jan 13 20:24:53 volumio-v1 bluetoothd[921]: Adv Monitor app :1.42 disconnected from D-Bus Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=info msg="zeroconf server listening on port 41069" Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 13 20:24:53 volumio-v1 volumio[1449]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetState Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=debug msg="obtained new client token: AABPMjXHVjX13FcwJTA/3ZzVs/40on1oO/KUrnAWN++7Kf9M3vgT+4qo4DnO2OBUsdONxxrsIkxrfjHYy6w/8TuOD1eSDNlI36M4DaNChFFBjH6yMYgn5CcpiezkFiCQKv+dYhvmV/yIiK5Sy3bq6KXzi4qIgpYu9KDecZTQcUGz59k2lzsFcRy9NTSke8M5i9Z9Bsid0UYO+zP0agDQy1DVji7HvI+QkQixEhhJpVne02B8VGJ2tbQawA==" Jan 13 20:24:53 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:53+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 13 20:24:53 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jan 13 20:24:54 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:54+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jan 13 20:24:54 volumio-v1 go-librespot[2212]: time="2026-01-13T20:24:54+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:24:54 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:54 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:55 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:55 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:57 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 13 20:24:57 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:57 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:24:57 volumio-v1 go-librespot[2237]: go-librespot daemon starting... Jan 13 20:24:57 volumio-v1 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="app state loaded" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=info msg="zeroconf server listening on port 39763" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="obtained new client token: AAATR+Qvqjf91IpPxyojbl+iaQgsCPTGPvPzZpfsuapsLjxt9Lf3OI63e2xZXNCZgb4xHURDsWb5KFSCG26j653Le+/1vnc8eLsevhVQlNQgqSf31xJdiGXFiHtbzw+srnhDSoLmQH+Ra+PomqwRIqg8MtbOjhKFJnb6JpIMhcKhBqaRH3mNLDin71gs/TX7xzaCsJUdvofOveqlswJWIjy4FfT+kO/66VUTqSXQxzCHIBJvFvW8Okhf9A==" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jan 13 20:24:57 volumio-v1 go-librespot[2238]: time="2026-01-13T20:24:57+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.86.250:53426->34.158.1.133:443: read: connection reset by peer" Jan 13 20:24:57 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:24:57 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:24:57 volumio-v1 systemd[1]: setdatetime-helper.service: Deactivated successfully. Jan 13 20:24:57 volumio-v1 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 13 20:24:58 volumio-v1 volumio-remote-updater[929]: Test mode disabled Jan 13 20:24:58 volumio-v1 volumio-remote-updater[929]: Alpha mode disabled Jan 13 20:24:58 volumio-v1 volumio-remote-updater[929]: Alpha legacy test mode disabled Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jan 13 20:24:58 volumio-v1 volumio[1449]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::volumioGetBrowseSources Jan 13 20:24:58 volumio-v1 volumio[1449]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 13 20:24:58 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:24:58 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:24:59 volumio-v1 volumio[1449]: info: BOOT COMPLETED Jan 13 20:25:00 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 13 20:25:00 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:00 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:00 volumio-v1 go-librespot[2274]: go-librespot daemon starting... Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=debug msg="app state loaded" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=info msg="zeroconf server listening on port 44249" Jan 13 20:25:00 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:00+01:00" level=debug msg="obtained new client token: AAAu2toZfIIt/iqNYV728DyX21wu6fl1Qp7zQc1dm3DLydKEV9x80ICHFME8aUJVIIBFzIzEuqfG2eIp9vi4ZArf95nLYtYZ/H4kmpuwE602f+PlupMWfst3QW2tLdV30mmzkRktSffMKkZqb/i2af+3x22arZ2DBLO+2OVdE7sGNbhUVMVHl+cSJx/Mh7xtVwdPr7WC0JxX5nrm0PSXTtAalnbGPHj30+1+2P+oi10QXS2kI/kLTiWjvw==" Jan 13 20:25:01 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:01+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:25:01 volumio-v1 go-librespot[2275]: time="2026-01-13T20:25:01+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:25:01 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:25:01 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:25:01 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:25:01 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:25:04 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 13 20:25:04 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:04 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:04 volumio-v1 go-librespot[2282]: go-librespot daemon starting... Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="app state loaded" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=info msg="zeroconf server listening on port 38271" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="obtained new client token: AABfnJILrsJkjTXN3BA9IA0hekPo6GSLOzfBHK9vrXFZNnLapiI0EGm6eQ/DxScIwM3wl+GT6qxOhIBgtkQU/BHgrjMxUTDHAC4sORmspdw0KzzYMbqfYag/WSF9d2aKnj6atHp5z9ZiQxvK4uQ+9XYBvxXi5NSalzVeUYxqqsLUUbepctdq9TyuRnnnklcB1ey2i3lDL4jP7zhNrw5OuASDjAQz6ELPgn1iUktCo6ZRJ/C458s4CXTF/g==" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:25:04 volumio-v1 go-librespot[2283]: time="2026-01-13T20:25:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:25:04 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:25:04 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:25:04 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:25:04 volumio-v1 volumio[1449]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:25:07 volumio-v1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 13 20:25:07 volumio-v1 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:07 volumio-v1 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 13 20:25:07 volumio-v1 go-librespot[2305]: go-librespot daemon starting... Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=info msg="running go-librespot 0.4.0" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="app state loaded" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=info msg="zeroconf server listening on port 39863" Jan 13 20:25:07 volumio-v1 volumio[1449]: info: Initializing connection to go-librespot Websocket Jan 13 20:25:07 volumio-v1 volumio[1449]: info: Connection to go-librespot Websocket established Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="new websocket client" Jan 13 20:25:07 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:07+01:00" level=debug msg="obtained new client token: AABsVdODkBAxv1seFAMijmpECgv5KkrYZ8ry+dlM3b/kKXt6G47msikdQEWr826pscE3y5kEK0nSfH/RyCalGTBDP/FYzQ/+BnRcQwNkDDbwWYWnql5Zl5yPI0yQq9JiTfVGgJXmHuHqSHH1q5cUyNbykLj9Ose2i/76pyZjTdJCTeNds3Cgye6XyG0B+PbNPkn7PxEIYjU450aPFoS0KWRB29aDHEflYqo+OcLlmSbc5EoZbSa2x/W/nw==" Jan 13 20:25:08 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:08+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 13 20:25:08 volumio-v1 go-librespot[2306]: time="2026-01-13T20:25:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Jan 13 20:25:08 volumio-v1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 13 20:25:08 volumio-v1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 13 20:25:08 volumio-v1 volumio[1449]: info: Connection to go-librespot Websocket closed Jan 13 20:25:10 volumio-v1 volumio[1449]: info: Getting Spotify volume Jan 13 20:25:10 volumio-v1 volumio[1449]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 13 20:25:10 volumio-v1 volumio[1449]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 13 20:25:10 volumio-v1 volumio[1449]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 13 20:25:10 volumio-v1 volumio[1449]: errno: -111, Jan 13 20:25:10 volumio-v1 volumio[1449]: code: 'ECONNREFUSED', Jan 13 20:25:10 volumio-v1 volumio[1449]: syscall: 'connect', Jan 13 20:25:10 volumio-v1 volumio[1449]: address: '127.0.0.1', Jan 13 20:25:10 volumio-v1 volumio[1449]: port: 9879, Jan 13 20:25:10 volumio-v1 volumio[1449]: response: undefined Jan 13 20:25:10 volumio-v1 volumio[1449]: } Jan 13 20:25:10 volumio-v1 volumio[1449]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 13 20:25:11 volumio-v1 sudo[2327]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-13 20:24' Jan 13 20:25:11 volumio-v1 sudo[2327]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"