Aug 31 19:10:00 spla-repro volumio[14817]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:00 spla-repro volumio[14817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:00 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:10:00.704+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 31 19:10:01 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Aug 31 19:10:01 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:01 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:01 spla-repro go-librespot[15145]: go-librespot daemon starting... Aug 31 19:10:01 spla-repro go-librespot[15146]: time="2026-08-31T19:10:01+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:01 spla-repro go-librespot[15146]: time="2026-08-31T19:10:01+02:00" level=debug msg="app state loaded" Aug 31 19:10:01 spla-repro go-librespot[15146]: time="2026-08-31T19:10:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=info msg="zeroconf server listening on port 45127" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:02 spla-repro volumio[14817]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="obtained new client token: AAGboKYeipn3mObC13Eu/mITk797Pk0Cj7xRe4XDnfUahG7x5eBTW4zK3Dziyhd95Riq3oGgB9clpJ/LJI1nQNXsQ/MixE9WjnvrBiY+Z5sKjgQip1Q3F1W1O56fTlDM/gOpu9SDDyOaCN9dqQlo1BhQaX+zTyzDFxr9eVzIOzEPeXwLSdtF8oRuh5lqBVauRl+dg48c/5cFJVSMD9Y5V00bi7NqJu96qIpc1eAIgPoxLRQ7C1cA+G8=" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=debug msg="completed challenge" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:02 spla-repro go-librespot[15146]: time="2026-08-31T19:10:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:02 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:02 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:03 spla-repro volumio[14817]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:03 spla-repro volumio[14817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin bluetooth to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin multiroom to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin metavolumio to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin cd_controller to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 31 19:10:05 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 31 19:10:05 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Aug 31 19:10:05 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:06 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:06 spla-repro go-librespot[15172]: go-librespot daemon starting... Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="app state loaded" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=info msg="zeroconf server listening on port 46267" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="obtained new client token: AAHUyghkCcdrk+5ZiAsTum8LsZQn779asRbmUKgBBDP2F0GlxN3dB6rnTtETFLMFA5ZSmc3CdhTFSrDbeN5Jm49Uyd2gxpmIXQNCjJLIhfVuJ4W1Qk1SrQxxdsngv0GS9moLHXufe7p4hIuSVgfccQN6Do09NF7nrqLLlNkna3vzVpp7LZ3W7cjwHTtFukNOnFzEtvxCXnpyGu4/6u2dCV8y84w66akqs+qNsrweCxJyhJ+7ZhKPDsggbw==" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=debug msg="completed challenge" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:06 spla-repro go-librespot[15173]: time="2026-08-31T19:10:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:06 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:06 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:07 spla-repro volumio[14817]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 31 19:10:07 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 31 19:10:07 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:07 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:07 spla-repro volumio[14817]: info: Starting MyVolumio Remote Streaming Endpoints Aug 31 19:10:07 spla-repro volumio[14817]: info: MyVolumio login type: Token Aug 31 19:10:07 spla-repro volumio[14817]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 31 19:10:07 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 31 19:10:08 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 31 19:10:08 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 31 19:10:08 spla-repro volumio[14817]: info: Streaming services startup Aug 31 19:10:08 spla-repro volumio[14817]: info: Starting Streaming Daemon Aug 31 19:10:08 spla-repro sudo[15183]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:08 spla-repro volumio[14817]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 31 19:10:08 spla-repro sudo[15183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:10:08 spla-repro sudo[15183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:08 spla-repro sudo[15183]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:08 spla-repro volumio[14817]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:08 spla-repro volumio[14817]: error: Cannot start Volumio Streaming Daemon Aug 31 19:10:08 spla-repro volumio[14817]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:10:08 spla-repro volumio[14817]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:08 spla-repro volumio[14817]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:10:08 spla-repro volumio[14817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:09 spla-repro volumio[14817]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 31 19:10:09 spla-repro volumio[14817]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:09 spla-repro volumio[14817]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:09 spla-repro volumio[14817]: info: Listing playlists Aug 31 19:10:09 spla-repro volumio[14817]: info: Listing playlists Aug 31 19:10:09 spla-repro volumio[14817]: info: MyVolumio token set successfully Aug 31 19:10:09 spla-repro volumio[14817]: info: MYVOLUMIO: Adding device Aug 31 19:10:09 spla-repro volumio[14817]: info: MYVOLUMIO: Evaluating Server Aug 31 19:10:09 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Aug 31 19:10:09 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:10 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:10 spla-repro go-librespot[15192]: go-librespot daemon starting... Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="app state loaded" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:10 spla-repro volumio[14817]: info: MyVolumio status changed Aug 31 19:10:10 spla-repro volumio[14817]: info: Streaming services startup Aug 31 19:10:10 spla-repro volumio[14817]: info: Starting Streaming Daemon Aug 31 19:10:10 spla-repro volumio[14817]: info: Removing browser output: myVolumio user plan is not superstar Aug 31 19:10:10 spla-repro volumio[14817]: info: Removing audio output: Aug 31 19:10:10 spla-repro volumio[14817]: info: Stoppping Tunnel 1 Aug 31 19:10:10 spla-repro sudo[15220]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:10 spla-repro sudo[15220]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:10:10 spla-repro sudo[15220]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:10 spla-repro sudo[15220]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:10 spla-repro volumio[14817]: error: Cannot start Volumio Streaming Daemon Aug 31 19:10:10 spla-repro volumio[14817]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:10:10 spla-repro volumio[14817]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:10 spla-repro volumio[14817]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:10:10 spla-repro sudo[15224]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:10 spla-repro sudo[15224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 31 19:10:10 spla-repro sudo[15224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=info msg="zeroconf server listening on port 41539" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro 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. Aug 31 19:10:10 spla-repro sudo[15224]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:10 spla-repro volumio[14817]: info: Remote SSH Stopped Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="obtained new client token: AAGYxDReDQpRw4kSenx9DYvpzu4Q/oEhrtsxBrqoOS5q3h0TeRGeoV9R5c/DzM+dD/rYQvxxJBUqsOJVicuu3gvt4LiGh8w8m6jx44WzYvmb5HQnDqwUaPRcAiw+yXc4D9mb/l5Yy+4BeWlGPjVc+HsPxmZaDcrQophcM+PpwSrOHF7AwqowG3B7+lzym9dkGGhXHn9c14H0tKC8495iwYb5XvgG+XP6IjSOqoo8PIzP5ENuK3j0FfgH9Q==" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=debug msg="completed challenge" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:10 spla-repro go-librespot[15193]: time="2026-08-31T19:10:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:10 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:10 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:11 spla-repro volumio[14817]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:11 spla-repro volumio[14817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:12 spla-repro volumio[14817]: info: Setting Geolocation for MyVolumio to eu6 Aug 31 19:10:12 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:12 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:12 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:12 spla-repro volumio[14817]: info: Successfully Added MyVolumio device Aug 31 19:10:13 spla-repro volumio[14817]: info: Updating MyVolumio device info Aug 31 19:10:13 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:13 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:13 spla-repro volumio[14817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:13 spla-repro volumio[14817]: info: Successfully Updated MyVolumio device Aug 31 19:10:13 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Aug 31 19:10:13 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:14 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:14 spla-repro go-librespot[15241]: go-librespot daemon starting... Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="app state loaded" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=info msg="zeroconf server listening on port 42437" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="obtained new client token: AAGqFrDgkxh0o9bpNJWLzG/p+41bbH6xP7Uz9uuuHSEkgOqEIC61zc60sQA2NdT9D9LQc0b8rrKesDrE5qQeUvB9tif0xtnjq5Juwp/cyR3q2CJzmzn7cuhyxTKMoCHbHdBSTpCt8qoVWARxuilEpp6a+icMxTCwxEZFqqAjrE0jXabx4HG4LH/02F8wfsJyrJbREiN69DrlpblGRx3E2tDd5xRAbcv/8h58H+6wyuvKiIIsdpbOqkhMcA==" Aug 31 19:10:14 spla-repro volumio[14817]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="new websocket client" Aug 31 19:10:14 spla-repro volumio[14817]: info: Connection to go-librespot Websocket established Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=debug msg="completed challenge" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:14 spla-repro go-librespot[15242]: time="2026-08-31T19:10:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:14 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:14 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:14 spla-repro volumio[14817]: info: Connection to go-librespot Websocket closed Aug 31 19:10:17 spla-repro volumio[14817]: info: Getting Spotify volume Aug 31 19:10:17 spla-repro volumio[14817]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:10:17 spla-repro volumio[14817]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:17 spla-repro volumio[14817]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 31 19:10:17 spla-repro volumio[14817]: errno: -111, Aug 31 19:10:17 spla-repro volumio[14817]: code: 'ECONNREFUSED', Aug 31 19:10:17 spla-repro volumio[14817]: syscall: 'connect', Aug 31 19:10:17 spla-repro volumio[14817]: address: '127.0.0.1', Aug 31 19:10:17 spla-repro volumio[14817]: port: 9879, Aug 31 19:10:17 spla-repro volumio[14817]: response: undefined Aug 31 19:10:17 spla-repro volumio[14817]: } Aug 31 19:10:17 spla-repro volumio[14817]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:10:17 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Aug 31 19:10:17 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:18 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:18 spla-repro go-librespot[15263]: go-librespot daemon starting... Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="app state loaded" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=info msg="zeroconf server listening on port 34667" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:18 spla-repro sudo[15275]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:18 spla-repro sudo[15275]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 19:09' Aug 31 19:10:18 spla-repro sudo[15275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="obtained new client token: AAFuzWnW6DVyWvJETyy2n25oQxg60gWFiTVo1lhiRFyPU0iVuOVwau9G69KGdhqTmVfV9taCsPrntZuAPBc1lqft5UYJ9BDUwIoRFZVYVqXwF7tVfEAc5Nizy/xXB6HSCR8Wl6kayMEmVoJfR3ZeihktXYIoswqbioVBpH2SGxDhUbgWm1+ytOZ0yL97eLyi9kWGXiVnked70GEKtIG5yg0DHOYcecJsnaaI5JlOOw+QbQrMv7uMcC11Yw==" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=debug msg="completed challenge" Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:18 spla-repro sudo[15275]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:18 spla-repro volumio[14817]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:18 spla-repro go-librespot[15264]: time="2026-08-31T19:10:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:18 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:18 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:18 spla-repro volumio-remote-updater[725]: [2026-08-31 19:10:18] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 31 19:10:18 spla-repro volumio-remote-updater[725]: [2026-08-31 19:10:18] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 31 19:10:18 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:10:18.950+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 31 19:10:18 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:10:18.952+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 31 19:10:18 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:18 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 31 19:10:18 spla-repro systemd[1]: volumio.service: Consumed 38.998s CPU time. Aug 31 19:10:19 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 31 19:10:19 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 15387. Aug 31 19:10:19 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 31 19:10:19 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 31 19:10:19 spla-repro systemd[1]: volumio.service: Consumed 38.998s CPU time. Aug 31 19:10:19 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 31 19:10:19 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:10:19.954+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 31 19:10:21 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:21 spla-repro volumio[15289]: info: ----- Volumio3 ---- Aug 31 19:10:21 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:21 spla-repro volumio[15289]: info: ----- System startup ---- Aug 31 19:10:21 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:21 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Aug 31 19:10:21 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:22 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:22 spla-repro go-librespot[15305]: go-librespot daemon starting... Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="app state loaded" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=info msg="zeroconf server listening on port 41091" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:22 spla-repro volumio[15289]: info: MYVOLUMIO Environment detected Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="obtained new client token: AAHVewNClJGfVuBQlnmMbfl+Q6T06Fv1f9QtCnDUkdda+iBH+GzQdgLKG5TT2o/268R924E4YWx/la5yzWroELgL/3DmtMzIusNio5vIyEvgzgoKm6aC6lYhC8BHA6ftvuy6dJjEbXu28RarV8+xSWc5mGANdPJn18MCtu8i83QQJFdsy/noqB9+f+AZaP3cKFjcqiLZL7gbGx58Qlw+aPQaoexAhraNWRyOfaF4085PTN22eXOtRbFCKA==" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:22 spla-repro volumio[15289]: info: Plugin folders cleanup Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning into folder /volumio/app/plugins/ Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category audio_interface Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category miscellanea Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category music_service Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category plugins.json Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category system_controller Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category user_interface Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=debug msg="completed challenge" Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning into folder /data/plugins/ Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category audio_interface Aug 31 19:10:22 spla-repro volumio[15289]: info: Scanning category music_service Aug 31 19:10:22 spla-repro volumio[15289]: info: Plugin folders cleanup completed Aug 31 19:10:22 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:22 spla-repro volumio[15289]: info: ----- Core plugins startup ---- Aug 31 19:10:22 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:22 spla-repro volumio[15289]: info: Loading plugins from folder /volumio/app/plugins/ Aug 31 19:10:22 spla-repro volumio[15289]: info: Adding plugin upnp to MyMusic Plugins Aug 31 19:10:22 spla-repro volumio[15289]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 31 19:10:22 spla-repro volumio[15289]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 31 19:10:22 spla-repro volumio[15289]: info: Loading plugins from folder /data/plugins/ Aug 31 19:10:22 spla-repro volumio[15289]: info: Loading plugin "system"... Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:22 spla-repro volumio[15289]: info: Loading plugin "appearance"... Aug 31 19:10:22 spla-repro go-librespot[15306]: time="2026-08-31T19:10:22+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:22 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:22 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:23 spla-repro volumio-remote-updater[725]: [2026-08-31 19:10:23] [connect] Successful connection Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "network"... Aug 31 19:10:24 spla-repro volumio[15289]: info: Refreshing Cached IP Addresses Aug 31 19:10:24 spla-repro sudo[15323]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:24 spla-repro sudo[15325]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:24 spla-repro sudo[15323]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "services"... Aug 31 19:10:24 spla-repro sudo[15325]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 19:10:24 spla-repro sudo[15325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:24 spla-repro sudo[15323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "volumio5onboarding"... Aug 31 19:10:24 spla-repro sudo[15325]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:24 spla-repro sudo[15323]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:24 spla-repro sudo[15332]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "alsa_controller"... Aug 31 19:10:24 spla-repro sudo[15332]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 31 19:10:24 spla-repro sudo[15332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:24 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "wizard"... Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "networkfs"... Aug 31 19:10:24 spla-repro volumio[15289]: info: Starting Udev Watcher for removable devices Aug 31 19:10:24 spla-repro volumio[15289]: info: Ignoring mount for partition: boot Aug 31 19:10:24 spla-repro volumio[15289]: info: Ignoring mount for partition: volumio Aug 31 19:10:24 spla-repro volumio[15289]: info: Ignoring mount for partition: volumio_data Aug 31 19:10:24 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "volumio_command_line_client"... Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "upnp"... Aug 31 19:10:24 spla-repro volumio[15289]: info: [1788196224604] Starting Upmpd Daemon Aug 31 19:10:24 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "my_music"... Aug 31 19:10:24 spla-repro volumio[15289]: info: Loading plugin "mpd"... Aug 31 19:10:25 spla-repro sudo[15332]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:25 spla-repro volumio[15289]: info: Loading plugin "upnp_browser"... Aug 31 19:10:25 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Aug 31 19:10:25 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:26 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:26 spla-repro go-librespot[15356]: go-librespot daemon starting... Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="app state loaded" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=info msg="zeroconf server listening on port 38073" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="obtained new client token: AAFiFLB5AmGecrX9bAlEfXe5ELRZKHxCxLBh8BpnVkj1vAzqAVlt+X3kp0UVMy9RLGQP88JV95XgdqVSg9o+CjBWAEELxk/On2QWk820CXUYxEg4VRHdcRvJOlzfOp9DIt6hiBhfmBROBaKc9x5fWyJl9zM9G6gNekki3j+2oY3UG+RkGvpjUfq5AGRc+YkSoIthfVjz+eRcVBK5oah+xuZqynNou7CKBauhi/Q9gF/Zqff9FoJG1e2ttQ==" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=debug msg="completed challenge" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:26 spla-repro go-librespot[15357]: time="2026-08-31T19:10:26+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:26 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:26 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:27 spla-repro volumio[15289]: info: Starting UPNP Browser Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "alarm-clock"... Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "airplay_emulation"... Aug 31 19:10:27 spla-repro volumio[15289]: info: Starting Shairport Sync Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "last_100"... Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "webradio"... Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "i2s_dacs"... Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "volumiodiscovery"... Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** For more information see Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:10:27 spla-repro volumio[15289]: *** WARNING *** For more information see Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** For more information see Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:10:27 spla-repro node[15289]: *** WARNING *** For more information see Aug 31 19:10:27 spla-repro volumio[15289]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 31 19:10:27 spla-repro volumio[15289]: info: Discovery: Started advertising with name: Spálňa-repro Aug 31 19:10:27 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:10:27 spla-repro volumio[15289]: info: Loading plugin "spop"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "outputs"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "albumart"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Plugin example_plugin is not enabled Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "inputs"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "updater_comm"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Plugin mpdemulation is not enabled Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "rest_api"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading plugin "websocket"... Aug 31 19:10:29 spla-repro volumio[15289]: info: Starting Socket.io Server version 1.7.4 Aug 31 19:10:29 spla-repro volumio[15289]: info: Plugin fusiondsp is not enabled Aug 31 19:10:29 spla-repro volumio[15289]: info: Loading i18n strings for locale sk Aug 31 19:10:29 spla-repro volumio[15289]: Updating browse sources language Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::initPlayerControls Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:10:29 spla-repro volumio[15289]: Express server listening on port 3000 Aug 31 19:10:29 spla-repro volumio[15289]: [Metrics] WebUI: 8s 926.88ms Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreStateMachine::resetVolumioState Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreStateMachine::getcurrentVolume Aug 31 19:10:29 spla-repro volumio[15289]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 19:10:29 spla-repro volumio[15289]: info: Cannot read play queue from file Aug 31 19:10:29 spla-repro volumio[15289]: info: Volumio Network Manager: Network status updated: 1 Aug 31 19:10:29 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Aug 31 19:10:29 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:30 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:30 spla-repro go-librespot[15384]: go-librespot daemon starting... Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 31 19:10:30 spla-repro volumio[15289]: Unable to parse: Aug 31 19:10:30 spla-repro volumio[15289]: Simple mixer control 'Master',0 Aug 31 19:10:30 spla-repro volumio[15289]: Capabilities: volume volume-joined Aug 31 19:10:30 spla-repro volumio[15289]: Playback channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Capture channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Limits: 0 - 248 Aug 31 19:10:30 spla-repro volumio[15289]: Mono: 112 [45%] Aug 31 19:10:30 spla-repro volumio[15289]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="app state loaded" Aug 31 19:10:30 spla-repro volumio[15368]: Forking 3 albumart workers Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 31 19:10:30 spla-repro volumio[15289]: Unable to parse: Aug 31 19:10:30 spla-repro volumio[15289]: Simple mixer control 'Master',0 Aug 31 19:10:30 spla-repro volumio[15289]: Capabilities: volume volume-joined Aug 31 19:10:30 spla-repro volumio[15289]: Playback channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Capture channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Limits: 0 - 248 Aug 31 19:10:30 spla-repro volumio[15289]: Mono: 112 [45%] Aug 31 19:10:30 spla-repro volumio[15289]: info: VolumeController:: Volume=undefined Mute =false Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::pushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioPushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::updateTrackBlock Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrackBlock Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::setRepeat null single undefined Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::pushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioPushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::setRandom null Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::pushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioPushState Aug 31 19:10:30 spla-repro volumio[15289]: info: Setting Device type: Raspberry PI Aug 31 19:10:30 spla-repro volumio[15289]: info: Completed loading Core Plugins Aug 31 19:10:30 spla-repro volumio[15289]: info: Preparing to generate the ALSA configuration file Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 31 19:10:30 spla-repro volumio[15289]: Unable to parse: Aug 31 19:10:30 spla-repro volumio[15289]: Simple mixer control 'Master',0 Aug 31 19:10:30 spla-repro volumio[15289]: Capabilities: volume volume-joined Aug 31 19:10:30 spla-repro volumio[15289]: Playback channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Capture channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Limits: 0 - 248 Aug 31 19:10:30 spla-repro volumio[15289]: Mono: 112 [45%] Aug 31 19:10:30 spla-repro volumio[15289]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: Found device kuchyna-repro Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=info msg="zeroconf server listening on port 34807" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: Found device kupelna-repro Aug 31 19:10:30 spla-repro volumio[15289]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="obtained new client token: AAGvBuLBMwa3a/tOrG9Wvbjd2QGW5FEN7oR4LkI0htp0NOmk7g8k9c7B2vyo+KepT9W0dpDQFPzytDuEle7J77ib5gJmslauqTy04by0ARVSGrg/4amScttIf9LY4aX//hdkTfERBK+pcM0ICO8T+j4kSGadS2/xs8EwVhe3mCKrhwuVYJJnB0HT65lCIhPFA+LNcYF/EG4/ngX/OFOMJqkgAq3sU/bc5xIF8v4GbaShemSV3UdnwU9QaQ==" Aug 31 19:10:30 spla-repro volumio[15289]: Unable to parse: Aug 31 19:10:30 spla-repro volumio[15289]: Simple mixer control 'Master',0 Aug 31 19:10:30 spla-repro volumio[15289]: Capabilities: volume volume-joined Aug 31 19:10:30 spla-repro volumio[15289]: Playback channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Capture channels: Mono Aug 31 19:10:30 spla-repro volumio[15289]: Limits: 0 - 248 Aug 31 19:10:30 spla-repro volumio[15289]: Mono: 112 [45%] Aug 31 19:10:30 spla-repro volumio[15289]: info: VolumeController:: Volume=undefined Mute =false Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreStateMachine::pushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioPushState Aug 31 19:10:30 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:30 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:30 spla-repro volumio[15289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:30 spla-repro go-librespot[15385]: time="2026-08-31T19:10:30+02:00" level=debug msg="completed challenge" Aug 31 19:10:31 spla-repro volumio[15289]: info: Asound.conf file unchanged, so no further update is needed Aug 31 19:10:31 spla-repro volumio[15289]: info: Output device has changed, restarting MPD Aug 31 19:10:31 spla-repro go-librespot[15385]: time="2026-08-31T19:10:31+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:31 spla-repro volumio[15289]: info: Output device has changed, restarting Shairport Sync Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:31 spla-repro sudo[15437]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:31 spla-repro sudo[15437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 19:10:31 spla-repro sudo[15437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:31 spla-repro sudo[15439]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:31 spla-repro sudo[15437]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:31 spla-repro volumio[15289]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:10:31 spla-repro volumio[15289]: info: ___________ START PLUGINS ___________ Aug 31 19:10:31 spla-repro go-librespot[15385]: time="2026-08-31T19:10:31+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:31 spla-repro sudo[15439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 19:10:31 spla-repro sudo[15439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:31 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:31 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:31 spla-repro volumio[15289]: info: ControllerMpd::onStart: Initializing MPD Aug 31 19:10:31 spla-repro volumio[15289]: info: Creating MPD Configuration file Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:10:31 spla-repro volumio[15289]: info: [1788196231280] CoreMusicLibrary::Adding element Mediálne servery Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:10:31 spla-repro sudo[15447]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:31 spla-repro volumio[15289]: info: UPNP Browser: Client initialized successfully Aug 31 19:10:31 spla-repro sudo[15451]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:31 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 19:10:31 spla-repro sudo[15447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 31 19:10:31 spla-repro sudo[15447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:31 spla-repro sudo[15449]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:31 spla-repro sudo[15451]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 19:10:31 spla-repro sudo[15451]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:31 spla-repro sudo[15449]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 19:10:31 spla-repro sudo[15449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:31 spla-repro sudo[15449]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:31 spla-repro volumio[15289]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:10:31 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 31 19:10:31 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 19:10:31 spla-repro systemd[1]: mpd.service: Consumed 6.634s CPU time. Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:31 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:31 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 19:10:31 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 19:10:31 spla-repro volumio[15289]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:10:31 spla-repro volumio[15289]: info: [1788196231587] CoreMusicLibrary::Adding element Last_100 Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:10:31 spla-repro volumio[15289]: info: [1788196231594] CoreMusicLibrary::Adding element Webradio Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:10:31 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:10:31 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 19:10:31 spla-repro volumio[15289]: info: Initializing BBC Radios Aug 31 19:10:31 spla-repro sudo[15447]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:31 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 31 19:10:31 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 19:10:31 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 31 19:10:31 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 19:10:31 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 19:10:31 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:31 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 19:10:31 spla-repro volumio[15289]: info: Creating Spotify config file Aug 31 19:10:31 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:32 spla-repro sudo[15479]: root : unable to resolve host spla-repro: System error Aug 31 19:10:32 spla-repro sudo[15479]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:32 spla-repro sudo[15479]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 19:10:32 spla-repro sudo[15479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 19:10:32 spla-repro sudo[15479]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:32 spla-repro volumio[15289]: info: Volumio Calling Home Aug 31 19:10:33 spla-repro volumio[15289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Aug 31 19:10:33 spla-repro volumio[15289]: info: Received Get System Info Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 19:10:33 spla-repro volumio[15394]: Starting albumart workers Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: Getting this device information Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:33 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 19:10:33 spla-repro volumio[15289]: info: Listing playlists Aug 31 19:10:33 spla-repro volumio[15289]: info: Listing playlists Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: Found device Spálňa-repro Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:33 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: Found device Spálňa-repro Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:33 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: Connected to remote: 192.168.200.201 Aug 31 19:10:33 spla-repro volumio[15396]: Starting albumart workers Aug 31 19:10:33 spla-repro volumio[15289]: info: MPD Permissions set Aug 31 19:10:33 spla-repro volumio[15289]: info: MPD Permissions set Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 31 19:10:33 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:33 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:33 spla-repro volumio[15289]: info: Discovery: Connected to remote: 192.168.200.202 Aug 31 19:10:33 spla-repro volumio[15289]: info: Volumio called home Aug 31 19:10:33 spla-repro volumio[15289]: info: Spotify config file written Aug 31 19:10:33 spla-repro sudo[15486]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:33 spla-repro sudo[15486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 31 19:10:34 spla-repro sudo[15486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:34 spla-repro volumio[15397]: Starting albumart workers Aug 31 19:10:34 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:34 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:10:34.224+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 31 19:10:34 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:34 spla-repro go-librespot[15488]: go-librespot daemon starting... Aug 31 19:10:34 spla-repro sudo[15486]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro go-librespot[15489]: time="2026-08-31T19:10:34+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:34 spla-repro go-librespot[15489]: time="2026-08-31T19:10:34+02:00" level=debug msg="app state loaded" Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro go-librespot[15489]: time="2026-08-31T19:10:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:10:34 spla-repro volumio[15289]: info: No need to fix Spotify hosts Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 31 19:10:34 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:34 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:34 spla-repro volumio[15289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 31 19:10:35 spla-repro sudo[15524]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:35 spla-repro sudo[15524]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 19:10:35 spla-repro sudo[15524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:35 spla-repro sudo[15524]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=info msg="zeroconf server listening on port 39121" Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:35 spla-repro sudo[15527]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:35 spla-repro sudo[15527]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 19:10:35 spla-repro sudo[15527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:35 spla-repro sudo[15527]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="obtained new client token: AAGpltdXZrEAykwnRE6Uw4sWL2R9hma5ZKAQltWFpO3WMpS8nsqbXR+D1qNqKvFurAe+pka4yMLqFlShLdWit6WxvT03kK1ZemKQblqFMQ9o/ZFy2jXvIMKT3cVUpPUg/QNihBVg6DsdHuRHUteqrKSDAG9qEv5SoCKlvx8jpM0x1CVm9CGPgGGEB/C534OOfeXuIwb8auvyMiyChJhSaB+/2YxcJqLDMFkGDcRl3wg/KALSq3KHy8AhHQ==" Aug 31 19:10:35 spla-repro volumio[15289]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 31 19:10:35 spla-repro volumio[15289]: info: Starting Shairport Sync Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:35 spla-repro volumio[15289]: info: Starting Shairport Sync Aug 31 19:10:35 spla-repro volumio[15289]: info: Starting Shairport Sync Aug 31 19:10:35 spla-repro sudo[15531]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=debug msg="completed challenge" Aug 31 19:10:35 spla-repro sudo[15531]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:10:35 spla-repro sudo[15531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:35 spla-repro sudo[15532]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:35 spla-repro sudo[15532]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:10:35 spla-repro sudo[15532]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:35 spla-repro sudo[15534]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:35 spla-repro sudo[15534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:10:35 spla-repro sudo[15534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:35 spla-repro go-librespot[15489]: time="2026-08-31T19:10:35+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:35 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:35 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:35 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:35 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:35 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 19:10:35 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 19:10:35 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 19:10:35 spla-repro systemd[1]: shairport-sync.service: Consumed 2.144s CPU time. Aug 31 19:10:36 spla-repro sudo[15545]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:36 spla-repro sudo[15545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 31 19:10:36 spla-repro sudo[15545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:36 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 19:10:36 spla-repro sudo[15531]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:36 spla-repro sudo[15532]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:36 spla-repro sudo[15534]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:36 spla-repro volumio[15289]: info: Shairport-Sync Started Aug 31 19:10:36 spla-repro volumio[15289]: Error adding Membership: Error: addMembership EINVAL Aug 31 19:10:36 spla-repro volumio[15289]: info: Shairport-Sync Started Aug 31 19:10:36 spla-repro volumio[15289]: info: Shairport-Sync Started Aug 31 19:10:36 spla-repro sudo[15545]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:36 spla-repro volumio[15289]: info: Upmpdcli Daemon Started Aug 31 19:10:36 spla-repro volumio-remote-updater[725]: [2026-08-31 19:10:36] [connect] Successful connection Aug 31 19:10:36 spla-repro volumio-remote-updater[725]: [2026-08-31 19:10:36] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788196236 101 Aug 31 19:10:36 spla-repro volumio[15289]: 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: 7 Aug 31 19:10:38 spla-repro volumio[15289]: info: go-librespot daemon successfully initialized Aug 31 19:10:38 spla-repro mpd[15481]: 2026-08-31T19:10:38 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 31 19:10:38 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 31 19:10:38 spla-repro sudo[15439]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:38 spla-repro sudo[15451]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:38 spla-repro volumio[15289]: info: Completed starting Core Plugins Aug 31 19:10:38 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:38 spla-repro volumio[15289]: info: ----- MyVolumio plugins startup ---- Aug 31 19:10:38 spla-repro volumio[15289]: info: ------------------------------------------- Aug 31 19:10:38 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 31 19:10:38 spla-repro volumio[15289]: error: MPD error: The expression evaluated to a falsy value: Aug 31 19:10:38 spla-repro volumio[15289]: assert.ok(self.idling) Aug 31 19:10:38 spla-repro volumio[15289]: error: The expression evaluated to a falsy value: Aug 31 19:10:38 spla-repro volumio[15289]: assert.ok(self.idling) Aug 31 19:10:38 spla-repro volumio[15289]: error: updateQueue error: null Aug 31 19:10:38 spla-repro volumio[15289]: info: MPD running with PID15481 Aug 31 19:10:38 spla-repro volumio[15289]: ,establishing connection Aug 31 19:10:38 spla-repro volumio[15289]: error: updateQueue error: null Aug 31 19:10:38 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Aug 31 19:10:38 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:39 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:39 spla-repro go-librespot[15578]: go-librespot daemon starting... Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="app state loaded" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=info msg="zeroconf server listening on port 40157" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="obtained new client token: AAHxacDhYZLshsQjdnF6NQAyKicwY6bI6WJd64LEmRZs21rrFkqbWgPObU1r4+zdnIpkod9VSr6tc/BHZrQX4N16Z72xsWCVcSfgwzp6+WM2Coth5ZYNgd94sYvvBEucW/jWi8mwpK4uxmumJp/nff4lw6jBX5TwQ/rsE3RcmxKa+VtCh3KkfYxOe1I7Vk4aUAmIhXA/tSoPk6KUFRLfrjKtacT9KIt2pCPbEgKW4WAHIt3T7hwFdn6zyA==" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=debug msg="completed challenge" Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:39 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:39 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:39 spla-repro go-librespot[15579]: time="2026-08-31T19:10:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:39 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:39 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:41 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:41 spla-repro volumio[15289]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:42 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Aug 31 19:10:42 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:43 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:43 spla-repro go-librespot[15588]: go-librespot daemon starting... Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="app state loaded" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=info msg="zeroconf server listening on port 42185" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="obtained new client token: AAEHnOH49kcbYfSLnt5J44pBQpTe6Qu7A3Wp5XfAk2qVGQCvdbJ/JUCKUGkA0FyNFcrDmmQ5/+vUhD1V2R3OQ6G/05AwDEwDkAIb/b0r0ibC03w9fEn1r/pWGVEqTSvcn/Co/37YHiwPrLYISVVfnCf7E/SqJm2fdrQGOMQ/GEjj3cw8boNL0f3bEIhvpBfbHc087pL+HEgM88wgTM5s9ApfPEQEP4jL+CZO7jeFY+RJKNBnzRTQv6W/Uw==" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=debug msg="completed challenge" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:43 spla-repro go-librespot[15589]: time="2026-08-31T19:10:43+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:43 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:43 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:43 spla-repro volumio[15289]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 31 19:10:44 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:44 spla-repro volumio[15289]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:46 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Aug 31 19:10:46 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:47 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:47 spla-repro go-librespot[15614]: go-librespot daemon starting... Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="app state loaded" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin bluetooth to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin multiroom to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin metavolumio to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin cd_controller to MyMusic Plugins Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=info msg="zeroconf server listening on port 40681" Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 31 19:10:47 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="obtained new client token: AAEO2doJL92GkE2xv5RmhhFqte/DUE9Otu4g2lXnPYkvXxNv8DKkt1sBZ39WAjAXLepzKRnwli7zv14kGic72LTi1G+q2S95J43HonN12ZBgTZt8rfO83XTZwW1PZFaVHwvUWNJ2Ft5RavR5aRZ0nMIXw49nWiACrY1hINLLqAsXafxqi+YulWbG45ybG1A7yDq4qJ5GWs+MI1+WUqKFx+cnsnSp4GFUWV2t6QjMjSdHCn5xV1xZmYVxSA==" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=debug msg="completed challenge" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:47 spla-repro go-librespot[15615]: time="2026-08-31T19:10:47+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:47 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:47 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:48 spla-repro volumio[15289]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 31 19:10:48 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 31 19:10:48 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:48 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:48 spla-repro volumio[15289]: info: Starting MyVolumio Remote Streaming Endpoints Aug 31 19:10:48 spla-repro volumio[15289]: info: MyVolumio login type: Token Aug 31 19:10:48 spla-repro volumio[15289]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 31 19:10:48 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 31 19:10:49 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 31 19:10:49 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 31 19:10:49 spla-repro volumio[15289]: info: Streaming services startup Aug 31 19:10:49 spla-repro volumio[15289]: info: Starting Streaming Daemon Aug 31 19:10:50 spla-repro sudo[15625]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:50 spla-repro volumio[15289]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 31 19:10:50 spla-repro sudo[15625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:10:50 spla-repro sudo[15625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:50 spla-repro sudo[15625]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:50 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:50 spla-repro volumio[15289]: error: Cannot start Volumio Streaming Daemon Aug 31 19:10:50 spla-repro volumio[15289]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:10:50 spla-repro volumio[15289]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:50 spla-repro volumio[15289]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:10:50 spla-repro volumio[15289]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:50 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:50 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:10:50 spla-repro volumio[15289]: info: Listing playlists Aug 31 19:10:50 spla-repro volumio[15289]: info: Listing playlists Aug 31 19:10:50 spla-repro volumio[15289]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 31 19:10:50 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Aug 31 19:10:50 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:51 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:51 spla-repro go-librespot[15631]: go-librespot daemon starting... Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="app state loaded" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=info msg="zeroconf server listening on port 43153" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:51 spla-repro volumio[15289]: info: MyVolumio token set successfully Aug 31 19:10:51 spla-repro volumio[15289]: info: MYVOLUMIO: Adding device Aug 31 19:10:51 spla-repro volumio[15289]: info: MYVOLUMIO: Evaluating Server Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="obtained new client token: AAEtJiwQAjz7UyboLauDtf4ofbPT+TlFKZkeRSKwmPFpFt7nvzRpfIXAjVxdwA2Kvpg4RD6Y52wV1cm7C8WWSDoAXK2AMyLgM525MXNSmur986SANXh4NWHSxDlk6BXfhdQJIFVer8TCMfkFFuR1IYPL+04MkIWrpw5p7vcIymkTiO1S+meoHR/roGyBfHZJvDDMTt5JGN1WIcCozjOM2XeGJGnf/tLqjtzQTHusMf5UyIUvijCFTBg0NQ==" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=debug msg="completed challenge" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:51 spla-repro go-librespot[15632]: time="2026-08-31T19:10:51+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:51 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:51 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:51 spla-repro volumio[15289]: info: MyVolumio status changed Aug 31 19:10:51 spla-repro volumio[15289]: info: Streaming services startup Aug 31 19:10:51 spla-repro volumio[15289]: info: Starting Streaming Daemon Aug 31 19:10:51 spla-repro volumio[15289]: info: Removing browser output: myVolumio user plan is not superstar Aug 31 19:10:51 spla-repro volumio[15289]: info: Removing audio output: Aug 31 19:10:51 spla-repro volumio[15289]: info: Stoppping Tunnel 1 Aug 31 19:10:51 spla-repro sudo[15662]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:51 spla-repro sudo[15662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:10:51 spla-repro sudo[15662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:51 spla-repro sudo[15662]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:52 spla-repro sudo[15665]: volumio : unable to resolve host spla-repro: System error Aug 31 19:10:52 spla-repro volumio[15289]: error: Cannot start Volumio Streaming Daemon Aug 31 19:10:52 spla-repro sudo[15665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 31 19:10:52 spla-repro volumio[15289]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:10:52 spla-repro volumio[15289]: sudo: unable to resolve host spla-repro: System error Aug 31 19:10:52 spla-repro volumio[15289]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:10:52 spla-repro sudo[15665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro 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. Aug 31 19:10:52 spla-repro sudo[15665]: pam_unix(sudo:session): session closed for user root Aug 31 19:10:52 spla-repro volumio[15289]: info: Remote SSH Stopped Aug 31 19:10:52 spla-repro volumio[15289]: info: Setting Geolocation for MyVolumio to eu6 Aug 31 19:10:52 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:52 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:52 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:52 spla-repro volumio[15289]: info: Successfully Added MyVolumio device Aug 31 19:10:53 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:53 spla-repro volumio[15289]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:53 spla-repro volumio[15289]: info: Updating MyVolumio device info Aug 31 19:10:53 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:53 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:53 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:10:53 spla-repro volumio[15289]: info: Successfully Updated MyVolumio device Aug 31 19:10:54 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Aug 31 19:10:54 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:55 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:55 spla-repro go-librespot[15681]: go-librespot daemon starting... Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="app state loaded" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=info msg="zeroconf server listening on port 34073" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="obtained new client token: AAEMwpwhSnMBtH9nic9fI+9+cEQutPwVGKmOuufBTbPzZp9CeI/6abXaV1QPQ+wOpoC+1L3qAl5/V+qESFGFJUpmCMSR8A0GiUd/Eo1x3Ws2khOtuEIWLInhA1ZUI6DHyxqhgXEM+1Ve0OB72IWqXBYgISEiYfOFLjPb3f3p9/U/VDe9Ya/2+b1aPLQWAU/g7Ks/J2SCVYbiOupNichSYed9JRuXEpw+/HTFoaPrfs3gmhP1FsypTme0Kw==" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="completed keyexchange" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=debug msg="completed challenge" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:10:55 spla-repro go-librespot[15682]: time="2026-08-31T19:10:55+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:10:55 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:10:55 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:10:56 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:56 spla-repro volumio[15289]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:10:58 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Aug 31 19:10:58 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:58 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:10:58 spla-repro go-librespot[15692]: go-librespot daemon starting... Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="app state loaded" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:10:59 spla-repro volumio[15289]: info: Initializing connection to go-librespot Websocket Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="new websocket client" Aug 31 19:10:59 spla-repro volumio[15289]: info: Connection to go-librespot Websocket established Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=info msg="zeroconf server listening on port 45561" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="obtained new client token: AAGtUR7VSBbG6wqGAmxMfDWrzDtKfRR1vo2mBQYhi1WAsmN6Zeb22sOpmna8EC7MIOO1hYXxMBQ1CScjDP8KjXotd0OvTdtrnJSp0xVTH4HG/L9O8HuWEyEXyTi2UVDLFSRvgTPUJIjE67WpqybCBY955Ruv74o7UWADRSS18pbCUsxCT8AhJy9/vBvpC0ZqDgvP2pSHN39KlkUWrXsOHUvJ0E8hWw1E+e8HHZ2JBiqbInVRucAds/iHYw==" Aug 31 19:10:59 spla-repro go-librespot[15693]: time="2026-08-31T19:10:59+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:10:59 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:10:59 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:02 spla-repro volumio[15289]: info: Getting Spotify volume Aug 31 19:11:02 spla-repro volumio[15289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 31 19:11:02 spla-repro volumio[15289]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:02 spla-repro volumio[15289]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:02 spla-repro go-librespot[15693]: time="2026-08-31T19:11:02+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:02 spla-repro go-librespot[15693]: time="2026-08-31T19:11:02+02:00" level=debug msg="completed challenge" Aug 31 19:11:02 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:11:02 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:02 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 19:11:02 spla-repro go-librespot[15693]: time="2026-08-31T19:11:02+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:02 spla-repro volumio-remote-updater[725]: Test mode disabled Aug 31 19:11:02 spla-repro volumio-remote-updater[725]: Alpha mode disabled Aug 31 19:11:02 spla-repro volumio-remote-updater[725]: Alpha legacy test mode disabled Aug 31 19:11:02 spla-repro volumio[15289]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 31 19:11:02 spla-repro go-librespot[15693]: time="2026-08-31T19:11:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:02 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:02 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:02 spla-repro volumio[15289]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:11:02 spla-repro volumio[15289]: Error: socket hang up Aug 31 19:11:02 spla-repro volumio[15289]: at connResetException (node:internal/errors:720:14) Aug 31 19:11:02 spla-repro volumio[15289]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 31 19:11:02 spla-repro volumio[15289]: at Socket.emit (node:events:526:35) Aug 31 19:11:02 spla-repro volumio[15289]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 31 19:11:02 spla-repro volumio[15289]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 31 19:11:02 spla-repro volumio[15289]: code: 'ECONNRESET', Aug 31 19:11:02 spla-repro volumio[15289]: response: undefined Aug 31 19:11:02 spla-repro volumio[15289]: } Aug 31 19:11:02 spla-repro volumio[15289]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:11:03 spla-repro sudo[15721]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:03 spla-repro sudo[15721]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 19:10' Aug 31 19:11:03 spla-repro sudo[15721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:03 spla-repro sudo[15721]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:04 spla-repro volumio[15289]: sudo: unable to resolve host spla-repro: System error Aug 31 19:11:04 spla-repro volumio-remote-updater[725]: [2026-08-31 19:11:04] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Aug 31 19:11:04 spla-repro volumio-remote-updater[725]: [2026-08-31 19:11:04] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Aug 31 19:11:04 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:11:04.324+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 31 19:11:04 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:04 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:11:04.329+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 31 19:11:04 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 31 19:11:04 spla-repro systemd[1]: volumio.service: Consumed 39.811s CPU time. Aug 31 19:11:04 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 31 19:11:04 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 31 19:11:04 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 15388. Aug 31 19:11:04 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 31 19:11:04 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 31 19:11:04 spla-repro systemd[1]: volumio.service: Consumed 39.811s CPU time. Aug 31 19:11:04 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 31 19:11:04 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 31 19:11:05 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:11:05.332+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 31 19:11:05 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Aug 31 19:11:05 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:06 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:06 spla-repro go-librespot[15752]: go-librespot daemon starting... Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="app state loaded" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:06 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:11:06.335+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=info msg="zeroconf server listening on port 38343" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="obtained new client token: AAG1Le0ZHO0Sq5jCIxJUjcMZi0vgZNFWtNOiEuPfgoXj/dJkiMPsJdsz+B2/dM8HyB54531gjjlCjAx6j1RvLmGMuSdoEdUn86sGaXiiITRgOKaiiS0KV2b93KCMXU8rSgd+FRr/niU+E4S5hoRHUVGZ+3FP8j4bysc1jg7gKrEGjzIHP4JYge5o2RNAw0mVpjN3v0ZcCTMlHUVbG+JfotjH3lUQ9tgY7DizYjo6UH1heN4b6ZAWy7fUIQ==" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=debug msg="completed challenge" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:06 spla-repro go-librespot[15753]: time="2026-08-31T19:11:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:06 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:06 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:07 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:07 spla-repro volumio[15737]: info: ----- Volumio3 ---- Aug 31 19:11:07 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:07 spla-repro volumio[15737]: info: ----- System startup ---- Aug 31 19:11:07 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:07 spla-repro volumio[15737]: info: MYVOLUMIO Environment detected Aug 31 19:11:08 spla-repro volumio[15737]: info: Plugin folders cleanup Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning into folder /volumio/app/plugins/ Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category audio_interface Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category miscellanea Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category music_service Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category plugins.json Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category system_controller Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category user_interface Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning into folder /data/plugins/ Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category audio_interface Aug 31 19:11:08 spla-repro volumio[15737]: info: Scanning category music_service Aug 31 19:11:08 spla-repro volumio[15737]: info: Plugin folders cleanup completed Aug 31 19:11:08 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:08 spla-repro volumio[15737]: info: ----- Core plugins startup ---- Aug 31 19:11:08 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:08 spla-repro volumio[15737]: info: Loading plugins from folder /volumio/app/plugins/ Aug 31 19:11:08 spla-repro volumio[15737]: info: Adding plugin upnp to MyMusic Plugins Aug 31 19:11:08 spla-repro volumio[15737]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 31 19:11:08 spla-repro volumio[15737]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 31 19:11:08 spla-repro volumio[15737]: info: Loading plugins from folder /data/plugins/ Aug 31 19:11:08 spla-repro volumio[15737]: info: Loading plugin "system"... Aug 31 19:11:08 spla-repro volumio[15737]: info: Loading plugin "appearance"... Aug 31 19:11:09 spla-repro volumio-remote-updater[725]: [2026-08-31 19:11:09] [connect] Successful connection Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "network"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Refreshing Cached IP Addresses Aug 31 19:11:09 spla-repro sudo[15775]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:09 spla-repro sudo[15777]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:09 spla-repro sudo[15775]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 19:11:09 spla-repro sudo[15777]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 19:11:09 spla-repro sudo[15777]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:09 spla-repro sudo[15775]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:09 spla-repro sudo[15777]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "services"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "volumio5onboarding"... Aug 31 19:11:09 spla-repro sudo[15784]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:09 spla-repro sudo[15775]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "alsa_controller"... Aug 31 19:11:09 spla-repro sudo[15784]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 31 19:11:09 spla-repro sudo[15784]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:09 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "wizard"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "networkfs"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Starting Udev Watcher for removable devices Aug 31 19:11:09 spla-repro volumio[15737]: info: Ignoring mount for partition: boot Aug 31 19:11:09 spla-repro volumio[15737]: info: Ignoring mount for partition: volumio Aug 31 19:11:09 spla-repro volumio[15737]: info: Ignoring mount for partition: volumio_data Aug 31 19:11:09 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "volumio_command_line_client"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "upnp"... Aug 31 19:11:09 spla-repro volumio[15737]: info: [1788196269846] Starting Upmpd Daemon Aug 31 19:11:09 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "my_music"... Aug 31 19:11:09 spla-repro volumio[15737]: info: Loading plugin "mpd"... Aug 31 19:11:09 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Aug 31 19:11:09 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:10 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:10 spla-repro go-librespot[15808]: go-librespot daemon starting... Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="app state loaded" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:10 spla-repro sudo[15784]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:10 spla-repro volumio[15737]: info: Loading plugin "upnp_browser"... Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=info msg="zeroconf server listening on port 40819" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="obtained new client token: AAH6DfAN6/DlikVGFYA7JAOHZXdRYBUyEwL+57VpzwcDB/McfXp5/8uge6jD+gEaaAs7Gni3+xoEMlxz503Rt/2cXacn5D2qtv8T+qi0MS5juleJTZYjxljCx5zscSAmKTszeLJidVe3w6EZQd2uFYbP3Z06HXNx9MlPXhp5j8ZJ9oX3eV76ynEjZ2r5CvGGNRkxXPvTv5QQ5NyD2enQztKv2TeGO0Gz6z0pJK+Xcjvv97rR2fb6dqCl2A==" Aug 31 19:11:10 spla-repro go-librespot[15809]: time="2026-08-31T19:11:10+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:11 spla-repro go-librespot[15809]: time="2026-08-31T19:11:11+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:11 spla-repro go-librespot[15809]: time="2026-08-31T19:11:11+02:00" level=debug msg="completed challenge" Aug 31 19:11:11 spla-repro go-librespot[15809]: time="2026-08-31T19:11:11+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:11 spla-repro go-librespot[15809]: time="2026-08-31T19:11:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:11 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:11 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:12 spla-repro volumio[15737]: info: Starting UPNP Browser Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "alarm-clock"... Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "airplay_emulation"... Aug 31 19:11:12 spla-repro volumio[15737]: info: Starting Shairport Sync Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "last_100"... Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "webradio"... Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "i2s_dacs"... Aug 31 19:11:12 spla-repro volumio[15737]: info: Loading plugin "volumiodiscovery"... Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** For more information see Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:11:12 spla-repro volumio[15737]: *** WARNING *** For more information see Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** For more information see Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 31 19:11:12 spla-repro node[15737]: *** WARNING *** For more information see Aug 31 19:11:12 spla-repro volumio[15737]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 31 19:11:12 spla-repro volumio[15737]: info: Discovery: Started advertising with name: Spálňa-repro Aug 31 19:11:13 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 31 19:11:13 spla-repro volumio[15737]: info: Loading plugin "spop"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "outputs"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "albumart"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Plugin example_plugin is not enabled Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "inputs"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "updater_comm"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Plugin mpdemulation is not enabled Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "rest_api"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading plugin "websocket"... Aug 31 19:11:14 spla-repro volumio[15737]: info: Starting Socket.io Server version 1.7.4 Aug 31 19:11:14 spla-repro volumio[15737]: info: Plugin fusiondsp is not enabled Aug 31 19:11:14 spla-repro volumio[15737]: info: Loading i18n strings for locale sk Aug 31 19:11:14 spla-repro volumio[15737]: Updating browse sources language Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:11:14 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Aug 31 19:11:14 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:14 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:14 spla-repro go-librespot[15830]: go-librespot daemon starting... Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::initPlayerControls Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:14 spla-repro go-librespot[15831]: time="2026-08-31T19:11:14+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:14 spla-repro go-librespot[15831]: time="2026-08-31T19:11:14+02:00" level=debug msg="app state loaded" Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:11:14 spla-repro volumio[15737]: Express server listening on port 3000 Aug 31 19:11:14 spla-repro volumio[15737]: [Metrics] WebUI: 8s 564.73ms Aug 31 19:11:14 spla-repro go-librespot[15831]: time="2026-08-31T19:11:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreStateMachine::resetVolumioState Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreStateMachine::getcurrentVolume Aug 31 19:11:14 spla-repro volumio[15737]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 19:11:14 spla-repro volumio[15737]: info: Cannot read play queue from file Aug 31 19:11:15 spla-repro volumio[15737]: info: Volumio Network Manager: Network status updated: 1 Aug 31 19:11:15 spla-repro volumio[15737]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 31 19:11:15 spla-repro volumio[15737]: Unable to parse: Aug 31 19:11:15 spla-repro volumio[15737]: Simple mixer control 'Master',0 Aug 31 19:11:15 spla-repro volumio[15737]: Capabilities: volume volume-joined Aug 31 19:11:15 spla-repro volumio[15737]: Playback channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Capture channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Limits: 0 - 248 Aug 31 19:11:15 spla-repro volumio[15737]: Mono: 112 [45%] Aug 31 19:11:15 spla-repro volumio[15737]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 31 19:11:15 spla-repro volumio[15737]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Aug 31 19:11:15 spla-repro volumio[15820]: Forking 3 albumart workers Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=info msg="zeroconf server listening on port 35431" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:15 spla-repro volumio[15737]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Aug 31 19:11:15 spla-repro volumio[15737]: info: Received Get System Info Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: Getting this device information Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 19:11:15 spla-repro volumio[15737]: Unable to parse: Aug 31 19:11:15 spla-repro volumio[15737]: Simple mixer control 'Master',0 Aug 31 19:11:15 spla-repro volumio[15737]: Capabilities: volume volume-joined Aug 31 19:11:15 spla-repro volumio[15737]: Playback channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Capture channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Limits: 0 - 248 Aug 31 19:11:15 spla-repro volumio[15737]: Mono: 112 [45%] Aug 31 19:11:15 spla-repro volumio[15737]: info: VolumeController:: Volume=undefined Mute =false Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::pushState Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioPushState Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::updateTrackBlock Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrackBlock Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioRetrievevolume Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::setRepeat null single undefined Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::pushState Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioPushState Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::setRandom null Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreStateMachine::pushState Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioPushState Aug 31 19:11:15 spla-repro volumio[15737]: info: Setting Device type: Raspberry PI Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="obtained new client token: AAGySDxTUWuk8ZhyhJ1gXJe835ObjEB7/RK/+dpcoHjReo7gkrolp2cIxxsBdYEc4Cl8bvnNOTGP/uTW/RBH2vaipqaYiQhK1MXjpzkIQsCItLfTa3dreWJCCX7FQOJdbMTUQ6jmPwWzk/GOQIZgWgxCzaXffDKCK1xWHGpWjV69rfDPIRvQeZlkDkB6qrurrzrkISY6stIH5/AUVg/CKQ+NEQB5GfgqC61jncnhlVdJreAQVO7P/f3a4Q==" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:15 spla-repro volumio[15737]: info: Completed loading Core Plugins Aug 31 19:11:15 spla-repro volumio[15737]: info: Preparing to generate the ALSA configuration file Aug 31 19:11:15 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:15 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=debug msg="completed challenge" Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: Found device kuchyna-repro Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:15 spla-repro volumio[15737]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 31 19:11:15 spla-repro volumio[15737]: Unable to parse: Aug 31 19:11:15 spla-repro volumio[15737]: Simple mixer control 'Master',0 Aug 31 19:11:15 spla-repro volumio[15737]: Capabilities: volume volume-joined Aug 31 19:11:15 spla-repro volumio[15737]: Playback channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Capture channels: Mono Aug 31 19:11:15 spla-repro volumio[15737]: Limits: 0 - 248 Aug 31 19:11:15 spla-repro volumio[15737]: Mono: 112 [45%] Aug 31 19:11:15 spla-repro volumio[15737]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 31 19:11:15 spla-repro volumio[15737]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 31 19:11:15 spla-repro volumio[15737]: info: Listing playlists Aug 31 19:11:15 spla-repro volumio[15737]: info: Listing playlists Aug 31 19:11:15 spla-repro go-librespot[15831]: time="2026-08-31T19:11:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:15 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:15 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: Found device kupelna-repro Aug 31 19:11:15 spla-repro volumio[15737]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 31 19:11:16 spla-repro volumio[15737]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 31 19:11:16 spla-repro volumio[15737]: Unable to parse: Aug 31 19:11:16 spla-repro volumio[15737]: Simple mixer control 'Master',0 Aug 31 19:11:16 spla-repro volumio[15737]: Capabilities: volume volume-joined Aug 31 19:11:16 spla-repro volumio[15737]: Playback channels: Mono Aug 31 19:11:16 spla-repro volumio[15737]: Capture channels: Mono Aug 31 19:11:16 spla-repro volumio[15737]: Limits: 0 - 248 Aug 31 19:11:16 spla-repro volumio[15737]: Mono: 112 [45%] Aug 31 19:11:16 spla-repro volumio[15737]: info: VolumeController:: Volume=undefined Mute =false Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreStateMachine::pushState Aug 31 19:11:16 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::volumioPushState Aug 31 19:11:16 spla-repro volumio[15737]: info: Asound.conf file unchanged, so no further update is needed Aug 31 19:11:16 spla-repro volumio[15737]: info: Output device has changed, restarting MPD Aug 31 19:11:16 spla-repro volumio[15737]: info: Output device has changed, restarting Shairport Sync Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:16 spla-repro sudo[15889]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:16 spla-repro sudo[15888]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:16 spla-repro sudo[15889]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 19:11:16 spla-repro sudo[15889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:16 spla-repro volumio[15737]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:11:16 spla-repro sudo[15888]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 19:11:16 spla-repro volumio[15737]: info: ___________ START PLUGINS ___________ Aug 31 19:11:16 spla-repro sudo[15888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:16 spla-repro sudo[15888]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:16 spla-repro volumio[15737]: info: ControllerMpd::onStart: Initializing MPD Aug 31 19:11:16 spla-repro volumio[15737]: info: Creating MPD Configuration file Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:11:16 spla-repro volumio[15737]: info: [1788196276296] CoreMusicLibrary::Adding element Mediálne servery Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:11:16 spla-repro sudo[15900]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:16 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 19:11:16 spla-repro volumio[15737]: info: UPNP Browser: Client initialized successfully Aug 31 19:11:16 spla-repro sudo[15900]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 19:11:16 spla-repro sudo[15900]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:16 spla-repro sudo[15897]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:16 spla-repro sudo[15901]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:16 spla-repro sudo[15900]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:16 spla-repro sudo[15897]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:16 spla-repro sudo[15897]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:16 spla-repro sudo[15901]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 19:11:16 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 31 19:11:16 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 19:11:16 spla-repro systemd[1]: mpd.service: Consumed 6.487s CPU time. Aug 31 19:11:16 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 31 19:11:16 spla-repro sudo[15901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:16 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 19:11:16 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 19:11:16 spla-repro volumio5-onboarding[5584]: time=2026-08-31T19:11:16.499+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 31 19:11:16 spla-repro volumio[15737]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:16 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 19:11:16 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 19:11:16 spla-repro volumio[15737]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:11:16 spla-repro volumio[15737]: info: [1788196276664] CoreMusicLibrary::Adding element Last_100 Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:11:16 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 19:11:16 spla-repro volumio[15737]: info: [1788196276671] CoreMusicLibrary::Adding element Webradio Aug 31 19:11:16 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 19:11:16 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 31 19:11:16 spla-repro sudo[15897]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:16 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 19:11:16 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:11:16 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 19:11:16 spla-repro volumio[15737]: info: Initializing BBC Radios Aug 31 19:11:16 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:16 spla-repro volumio[15737]: info: Creating Spotify config file Aug 31 19:11:16 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:17 spla-repro sudo[15918]: root : unable to resolve host spla-repro: System error Aug 31 19:11:17 spla-repro sudo[15918]: sudo: unable to resolve host spla-repro: System error Aug 31 19:11:17 spla-repro sudo[15918]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 19:11:17 spla-repro sudo[15918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 19:11:17 spla-repro sudo[15918]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:17 spla-repro volumio[15737]: info: Volumio Calling Home Aug 31 19:11:18 spla-repro volumio[15737]: info: Discovery: Connected to remote: 192.168.200.201 Aug 31 19:11:18 spla-repro volumio[15851]: Starting albumart workers Aug 31 19:11:18 spla-repro volumio[15737]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 31 19:11:18 spla-repro volumio[15737]: info: Discovery: Found device Spálňa-repro Aug 31 19:11:18 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:18 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:18 spla-repro volumio[15737]: info: MPD Permissions set Aug 31 19:11:18 spla-repro volumio[15737]: info: MPD Permissions set Aug 31 19:11:18 spla-repro volumio[15737]: info: Discovery: Connected to remote: 192.168.200.202 Aug 31 19:11:18 spla-repro volumio[15737]: info: Spotify config file written Aug 31 19:11:18 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 31 19:11:18 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:18 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:18 spla-repro sudo[15936]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:18 spla-repro volumio[15853]: Starting albumart workers Aug 31 19:11:18 spla-repro sudo[15936]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 31 19:11:18 spla-repro sudo[15936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:18 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:18 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:18 spla-repro go-librespot[15938]: go-librespot daemon starting... Aug 31 19:11:18 spla-repro sudo[15936]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 31 19:11:19 spla-repro volumio[15737]: info: Volumio called home Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=debug msg="app state loaded" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:19 spla-repro volumio[15854]: Starting albumart workers Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 19:11:19 spla-repro volumio[15737]: info: No need to fix Spotify hosts Aug 31 19:11:19 spla-repro volumio[15737]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 31 19:11:19 spla-repro volumio[15737]: info: Discovery: Found device Spálňa-repro Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:19 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=info msg="zeroconf server listening on port 46185" Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:19 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:19 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:19 spla-repro volumio[15737]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 31 19:11:19 spla-repro go-librespot[15939]: time="2026-08-31T19:11:19+02:00" level=debug msg="obtained new client token: AAFcOAXkuXLUINvErBtBLwRcRhJ9Nc9//B9lVtoq6h60aKuLbvHbh+7cT499iK/m+Rmlg2vRUqh32c73sRUOu6vAH/X68vGSEoP13Un1jihpPbcFCM4c3EPmyzozORDKgDu0uFBDSwpaU0WIHll2W/+cYTdv6MWVxUCugc5SfdbmlRraKHos/iMZEuqbz8DPmsnhJivLNCnUM0MBnpsQQrjyYg+nTkiKw9hFJ5fXVrInVohrj+Efg70h3w==" Aug 31 19:11:20 spla-repro go-librespot[15939]: time="2026-08-31T19:11:20+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:20 spla-repro sudo[15973]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro go-librespot[15939]: time="2026-08-31T19:11:20+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:20 spla-repro go-librespot[15939]: time="2026-08-31T19:11:20+02:00" level=debug msg="completed challenge" Aug 31 19:11:20 spla-repro volumio[15737]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 31 19:11:20 spla-repro sudo[15973]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 19:11:20 spla-repro sudo[15973]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro sudo[15975]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro go-librespot[15939]: time="2026-08-31T19:11:20+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:20 spla-repro sudo[15973]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:20 spla-repro sudo[15975]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 19:11:20 spla-repro sudo[15975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro sudo[15975]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:20 spla-repro volumio[15737]: info: Starting Shairport Sync Aug 31 19:11:20 spla-repro volumio[15737]: info: Starting Shairport Sync Aug 31 19:11:20 spla-repro go-librespot[15939]: time="2026-08-31T19:11:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:20 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:20 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:20 spla-repro volumio[15737]: info: Starting Shairport Sync Aug 31 19:11:20 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:20 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:20 spla-repro sudo[15979]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro sudo[15979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:11:20 spla-repro sudo[15979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro sudo[15981]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro sudo[15983]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro sudo[15983]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:11:20 spla-repro sudo[15983]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro sudo[15981]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 19:11:20 spla-repro sudo[15981]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 19:11:20 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 19:11:20 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 19:11:20 spla-repro systemd[1]: shairport-sync.service: Consumed 2.097s CPU time. Aug 31 19:11:20 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:20 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:20 spla-repro sudo[15992]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:20 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 19:11:20 spla-repro sudo[15981]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:20 spla-repro sudo[15992]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 31 19:11:20 spla-repro sudo[15983]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:20 spla-repro sudo[15992]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:20 spla-repro sudo[15979]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:21 spla-repro sudo[15992]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:21 spla-repro volumio[15737]: info: Shairport-Sync Started Aug 31 19:11:21 spla-repro volumio[15737]: Error adding Membership: Error: addMembership EINVAL Aug 31 19:11:21 spla-repro volumio[15737]: info: Shairport-Sync Started Aug 31 19:11:21 spla-repro volumio[15737]: info: Shairport-Sync Started Aug 31 19:11:21 spla-repro volumio[15737]: info: Upmpdcli Daemon Started Aug 31 19:11:21 spla-repro volumio-remote-updater[725]: [2026-08-31 19:11:21] [connect] Successful connection Aug 31 19:11:21 spla-repro volumio-remote-updater[725]: [2026-08-31 19:11:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788196281 101 Aug 31 19:11:21 spla-repro volumio[15737]: 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: 7 Aug 31 19:11:22 spla-repro volumio[15737]: info: go-librespot daemon successfully initialized Aug 31 19:11:23 spla-repro mpd[15931]: 2026-08-31T19:11:23 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 31 19:11:23 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Aug 31 19:11:23 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 31 19:11:23 spla-repro sudo[15889]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:23 spla-repro sudo[15901]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:23 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:23 spla-repro volumio[15737]: info: Completed starting Core Plugins Aug 31 19:11:23 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:23 spla-repro volumio[15737]: info: ----- MyVolumio plugins startup ---- Aug 31 19:11:23 spla-repro volumio[15737]: info: ------------------------------------------- Aug 31 19:11:23 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 31 19:11:23 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:23 spla-repro go-librespot[16026]: go-librespot daemon starting... Aug 31 19:11:23 spla-repro go-librespot[16028]: time="2026-08-31T19:11:23+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:23 spla-repro go-librespot[16028]: time="2026-08-31T19:11:23+02:00" level=debug msg="app state loaded" Aug 31 19:11:23 spla-repro go-librespot[16028]: time="2026-08-31T19:11:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:23 spla-repro volumio[15737]: error: MPD error: The expression evaluated to a falsy value: Aug 31 19:11:23 spla-repro volumio[15737]: assert.ok(self.idling) Aug 31 19:11:23 spla-repro volumio[15737]: error: The expression evaluated to a falsy value: Aug 31 19:11:23 spla-repro volumio[15737]: assert.ok(self.idling) Aug 31 19:11:23 spla-repro volumio[15737]: info: MPD running with PID15931 Aug 31 19:11:23 spla-repro volumio[15737]: ,establishing connection Aug 31 19:11:23 spla-repro volumio[15737]: error: updateQueue error: null Aug 31 19:11:23 spla-repro volumio[15737]: error: updateQueue error: null Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=info msg="zeroconf server listening on port 35677" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="obtained new client token: AAEAEV+EmNPeGhR4Woe0Fj1d3gQflkgjrL8OocroxruJNlVgm2nsTjNvF1bKk12Cnib8t3BVu5bjTmnFSgqZRnbx1z4Jn5ZKzDnKRb3FXn2rLhX5V1p/66skqUNPu3UtB3QNSJf5bLk6Z6KJHcYxG0hQFdlQQMnwMEFwGcQzbyUF6xe1cvjRNrlZNDnEY0CRRt/2c09swX9qUYCsd0P1RYGJS5c8ZWOf9gEQk9QCf54Mg8c3P6uqDpQ=" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:24 spla-repro go-librespot[16028]: time="2026-08-31T19:11:24+02:00" level=debug msg="completed challenge" Aug 31 19:11:25 spla-repro go-librespot[16028]: time="2026-08-31T19:11:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:25 spla-repro go-librespot[16028]: time="2026-08-31T19:11:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:25 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:25 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:25 spla-repro volumio[15737]: info: Initializing connection to go-librespot Websocket Aug 31 19:11:25 spla-repro volumio[15737]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:11:28 spla-repro volumio[15737]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 31 19:11:28 spla-repro volumio[15737]: info: Initializing connection to go-librespot Websocket Aug 31 19:11:28 spla-repro volumio[15737]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:11:28 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Aug 31 19:11:28 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:29 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:29 spla-repro go-librespot[16038]: go-librespot daemon starting... Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="app state loaded" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=info msg="zeroconf server listening on port 34713" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="obtained new client token: AAHu1MuU/eqGoTlLxXZAOtYDHUiBbJM83OArWcUGWQR1BeilET9JouUesbDP34hCLHUixEwriScVoBI3oq/11vJnhBpuviylq7v+XLj7mG6ISuA6B6WiyrtqWkD3w3Y76LE5PwPXz3Z/5H3+JGY7snQbLYXBRtM5fV9+uDAQkaG+phR/7sk8LP+qF5JsIGmPpuBXqTnr6HUqbIjow2x4Fy+GWsLj+D9mQEu7iwslfuMqzUNGHr9nS9j04A==" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=debug msg="completed challenge" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:29 spla-repro go-librespot[16039]: time="2026-08-31T19:11:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:29 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:29 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:29 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:31 spla-repro volumio[15737]: info: Initializing connection to go-librespot Websocket Aug 31 19:11:31 spla-repro volumio[15737]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 31 19:11:31 spla-repro volumio[15737]: info: Adding plugin bluetooth to MyMusic Plugins Aug 31 19:11:31 spla-repro volumio[15737]: info: Adding plugin multiroom to MyMusic Plugins Aug 31 19:11:31 spla-repro volumio[15737]: info: Adding plugin metavolumio to MyMusic Plugins Aug 31 19:11:31 spla-repro volumio[15737]: info: Adding plugin cd_controller to MyMusic Plugins Aug 31 19:11:32 spla-repro volumio[15737]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 31 19:11:32 spla-repro volumio[15737]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 31 19:11:32 spla-repro volumio[15737]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 31 19:11:32 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 31 19:11:32 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Aug 31 19:11:32 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:33 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:33 spla-repro go-librespot[16062]: go-librespot daemon starting... Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="app state loaded" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:33 spla-repro volumio[15737]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 31 19:11:33 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 31 19:11:33 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:33 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:33 spla-repro volumio[15737]: info: Starting MyVolumio Remote Streaming Endpoints Aug 31 19:11:33 spla-repro volumio[15737]: info: MyVolumio login type: Token Aug 31 19:11:33 spla-repro volumio[15737]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 31 19:11:33 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=info msg="zeroconf server listening on port 40781" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="obtained new client token: AAFu8+ds0ZbpTasw9tU67eXofR00MUEhINWHvm/9GkFfUgzuTfB6PiEVdOUMyo8XhTdSa3qV3e6thOuWbNG8NPlrOIaNgsw8mKc2I0ZU32qXX8qXFMpFVicUU8+Zdlh4iVjgYaBYKALCoh8lW/kWWt+qFVEcIQZdXfkqX3k1onFFnBorkTkkt+lSBfCl8JXgDpMXOrv7tRRP0OguUJoY6KzFO+uOKWux/oF6fufrjw8RX+oLwZBDDKxl7w==" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=debug msg="completed challenge" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:33 spla-repro go-librespot[16063]: time="2026-08-31T19:11:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:34 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 31 19:11:34 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 31 19:11:34 spla-repro volumio[15737]: info: Streaming services startup Aug 31 19:11:34 spla-repro volumio[15737]: info: Starting Streaming Daemon Aug 31 19:11:34 spla-repro sudo[16074]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:34 spla-repro volumio[15737]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 31 19:11:34 spla-repro sudo[16074]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:11:34 spla-repro sudo[16074]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:34 spla-repro sudo[16074]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:34 spla-repro volumio[15737]: info: Initializing connection to go-librespot Websocket Aug 31 19:11:34 spla-repro volumio[15737]: error: Cannot start Volumio Streaming Daemon Aug 31 19:11:34 spla-repro volumio[15737]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:11:34 spla-repro volumio[15737]: sudo: unable to resolve host spla-repro: System error Aug 31 19:11:34 spla-repro volumio[15737]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:11:34 spla-repro volumio[15737]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:11:35 spla-repro volumio[15737]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 31 19:11:36 spla-repro volumio[15737]: info: MyVolumio token set successfully Aug 31 19:11:36 spla-repro volumio[15737]: info: MYVOLUMIO: Adding device Aug 31 19:11:36 spla-repro volumio[15737]: info: MYVOLUMIO: Evaluating Server Aug 31 19:11:36 spla-repro volumio[15737]: info: MyVolumio status changed Aug 31 19:11:36 spla-repro volumio[15737]: info: Streaming services startup Aug 31 19:11:36 spla-repro volumio[15737]: info: Starting Streaming Daemon Aug 31 19:11:36 spla-repro volumio[15737]: info: Removing browser output: myVolumio user plan is not superstar Aug 31 19:11:36 spla-repro volumio[15737]: info: Removing audio output: Aug 31 19:11:36 spla-repro volumio[15737]: info: Stoppping Tunnel 1 Aug 31 19:11:36 spla-repro sudo[16102]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:36 spla-repro sudo[16102]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 31 19:11:36 spla-repro sudo[16102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:36 spla-repro sudo[16105]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:36 spla-repro sudo[16102]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:36 spla-repro sudo[16105]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 31 19:11:36 spla-repro volumio[15737]: error: Cannot start Volumio Streaming Daemon Aug 31 19:11:36 spla-repro volumio[15737]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 31 19:11:36 spla-repro volumio[15737]: sudo: unable to resolve host spla-repro: System error Aug 31 19:11:36 spla-repro volumio[15737]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 31 19:11:36 spla-repro sudo[16105]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro 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. Aug 31 19:11:36 spla-repro sudo[16105]: pam_unix(sudo:session): session closed for user root Aug 31 19:11:36 spla-repro volumio[15737]: info: Remote SSH Stopped Aug 31 19:11:36 spla-repro volumio[15737]: info: Setting Geolocation for MyVolumio to eu4 Aug 31 19:11:36 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:36 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:36 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:37 spla-repro volumio[15737]: info: Successfully Added MyVolumio device Aug 31 19:11:37 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Aug 31 19:11:37 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:37 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:37 spla-repro go-librespot[16107]: go-librespot daemon starting... Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="app state loaded" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=info msg="zeroconf server listening on port 34033" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:37 spla-repro volumio[15737]: info: Updating MyVolumio device info Aug 31 19:11:37 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:37 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:37 spla-repro volumio[15737]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="obtained new client token: AAGJ6HsM8UpytBTT0pcI+VRrww8Sc6biHy+kbtLS5v06V6A9j37kwQq6jbIFAl7lEuYmBzUHPDLwB5c4vHaN5OKUGvEfB7pCjKij0cn4ptN7U+4tQs4tVnzLPmqljW5fDsMCkqFovANBxMBQuhkdc8BQIqnwsLZLjS6fQd+Ger32qQ4EsH6Zv794LNApZm40BP/Z9At2iEYBhpGBSi91w5NlmDHx3jvEo2UF5uxbBAw30fFPGoUPBjQrtg==" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="completed challenge" Aug 31 19:11:37 spla-repro volumio[15737]: info: Initializing connection to go-librespot Websocket Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=debug msg="new websocket client" Aug 31 19:11:37 spla-repro volumio[15737]: info: Connection to go-librespot Websocket established Aug 31 19:11:37 spla-repro go-librespot[16108]: time="2026-08-31T19:11:37+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:38 spla-repro go-librespot[16108]: time="2026-08-31T19:11:38+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:38 spla-repro volumio[15737]: info: Connection to go-librespot Websocket closed Aug 31 19:11:38 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:38 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 19:11:38 spla-repro volumio[15737]: info: Successfully Updated MyVolumio device Aug 31 19:11:39 spla-repro volumio[15737]: info: CoreCommandRouter::volumioGetState Aug 31 19:11:39 spla-repro volumio[15737]: info: CorePlayQueue::getTrack 0 Aug 31 19:11:39 spla-repro volumio[15737]: info: Listing playlists Aug 31 19:11:39 spla-repro volumio[15737]: info: Listing playlists Aug 31 19:11:40 spla-repro volumio[15737]: info: Getting Spotify volume Aug 31 19:11:40 spla-repro volumio[15737]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:11:40 spla-repro volumio[15737]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 19:11:40 spla-repro volumio[15737]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 31 19:11:40 spla-repro volumio[15737]: errno: -111, Aug 31 19:11:40 spla-repro volumio[15737]: code: 'ECONNREFUSED', Aug 31 19:11:40 spla-repro volumio[15737]: syscall: 'connect', Aug 31 19:11:40 spla-repro volumio[15737]: address: '127.0.0.1', Aug 31 19:11:40 spla-repro volumio[15737]: port: 9879, Aug 31 19:11:40 spla-repro volumio[15737]: response: undefined Aug 31 19:11:40 spla-repro volumio[15737]: } Aug 31 19:11:40 spla-repro volumio[15737]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 19:11:41 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. Aug 31 19:11:41 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:41 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 19:11:41 spla-repro go-librespot[16145]: go-librespot daemon starting... Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=info msg="running go-librespot 0.7.1" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="app state loaded" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=info msg="zeroconf server listening on port 38805" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="obtained new client token: AAE+r75tyVkftkwKO6rtLQahbD1fxQ0HNYxZXCxV/Al0CE9pwMcNjcnfdDk+1zgm5JBrrd1uGlfs3BdQ5KTp0lMh4Emece++rJkUd93wRGPRjaDaI2PCUYb0nhS+pfQwOkETYiUstkP+R6XTf9/cFDvVY3GUHzBr5U7ox2Z/jz233nBxfCrtj0LmaD1bkL2tIhgCJOzW1JLJXpuDitAH6wzNrm+He4C1YD/I97qyJzL2fQ5og9xziQiZTg==" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="completed keyexchange" Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=debug msg="completed challenge" Aug 31 19:11:41 spla-repro sudo[16158]: volumio : unable to resolve host spla-repro: System error Aug 31 19:11:41 spla-repro sudo[16158]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 19:10' Aug 31 19:11:41 spla-repro sudo[16158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 19:11:41 spla-repro go-librespot[16146]: time="2026-08-31T19:11:41+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 31 19:11:42 spla-repro go-librespot[16146]: time="2026-08-31T19:11:42+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 19:11:42 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 19:11:42 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"