Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin bluetooth to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin multiroom to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin metavolumio to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin cd_controller to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 28 21:04:01 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 21:04:02 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Aug 28 21:04:02 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:02 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:02 spla-repro go-librespot[21288]: go-librespot daemon starting... Aug 28 21:04:02 spla-repro go-librespot[21289]: time="2026-08-28T21:04:02+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:02 spla-repro go-librespot[21289]: time="2026-08-28T21:04:02+02:00" level=debug msg="app state loaded" Aug 28 21:04:02 spla-repro volumio[20938]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 21:04:02 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 21:04:02 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:02 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:02 spla-repro volumio[20938]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 21:04:02 spla-repro go-librespot[21289]: time="2026-08-28T21:04:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:02 spla-repro volumio[20938]: info: MyVolumio login type: Token Aug 28 21:04:02 spla-repro volumio[20938]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 21:04:02 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+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 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+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 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+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 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=info msg="zeroconf server listening on port 32869" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=debug msg="obtained new client token: AAE5iEVaAyumvjYxK4Jm/i5dYfgVJUvSrFKWNYUYnURWh7j8KFcWcd6WT7rzItIFqA2pc/kvueP9EHNlsyNFoGKsKos7LF4xdaUCpox9HtqWRAzk7PlhNLp2ibrSlXvmUkAtCJkU4SHZrm4+QzqNE8YZyxo/xrhCdDICVcbb+gahSB02D7KmmWVqa2UhYCb2Ix8VpYZ4J+wy5vvP/c62Plqx0ppsSj1L3VolNMXNrfK8RSWQmtqkXW4gjA==" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+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 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=debug msg="completed challenge" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:03 spla-repro go-librespot[21289]: time="2026-08-28T21:04:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:03 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:03 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:04 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 28 21:04:04 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 28 21:04:04 spla-repro volumio[20938]: info: Streaming services startup Aug 28 21:04:04 spla-repro volumio[20938]: info: Starting Streaming Daemon Aug 28 21:04:04 spla-repro sudo[21299]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:04 spla-repro volumio[20938]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 28 21:04:04 spla-repro sudo[21299]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 21:04:04 spla-repro sudo[21299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:04 spla-repro sudo[21299]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:04 spla-repro volumio[20938]: info: Initializing connection to go-librespot Websocket Aug 28 21:04:04 spla-repro volumio[20938]: error: Cannot start Volumio Streaming Daemon Aug 28 21:04:04 spla-repro volumio[20938]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 21:04:04 spla-repro volumio[20938]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:04 spla-repro volumio[20938]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 21:04:04 spla-repro volumio[20938]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:04:04 spla-repro volumio[20938]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 28 21:04:05 spla-repro volumio[20938]: info: MyVolumio token set successfully Aug 28 21:04:05 spla-repro volumio[20938]: info: MYVOLUMIO: Adding device Aug 28 21:04:05 spla-repro volumio[20938]: info: MYVOLUMIO: Evaluating Server Aug 28 21:04:05 spla-repro volumio[20938]: info: MyVolumio status changed Aug 28 21:04:05 spla-repro volumio[20938]: info: Streaming services startup Aug 28 21:04:05 spla-repro volumio[20938]: info: Starting Streaming Daemon Aug 28 21:04:05 spla-repro volumio[20938]: info: Removing browser output: myVolumio user plan is not superstar Aug 28 21:04:05 spla-repro volumio[20938]: info: Removing audio output: Aug 28 21:04:05 spla-repro volumio[20938]: info: Stoppping Tunnel 1 Aug 28 21:04:05 spla-repro sudo[21327]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:05 spla-repro sudo[21327]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 21:04:05 spla-repro sudo[21327]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:05 spla-repro sudo[21327]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:05 spla-repro sudo[21330]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:05 spla-repro sudo[21330]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 28 21:04:05 spla-repro sudo[21330]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:05 spla-repro volumio[20938]: error: Cannot start Volumio Streaming Daemon Aug 28 21:04:05 spla-repro volumio[20938]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 21:04:05 spla-repro volumio[20938]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:05 spla-repro volumio[20938]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 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 28 21:04:05 spla-repro sudo[21330]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:05 spla-repro volumio[20938]: info: Remote SSH Stopped Aug 28 21:04:05 spla-repro volumio[20938]: info: Setting Geolocation for MyVolumio to eu6 Aug 28 21:04:05 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:05 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:05 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:06 spla-repro volumio[20938]: info: Successfully Added MyVolumio device Aug 28 21:04:06 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Aug 28 21:04:06 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:06 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:06 spla-repro go-librespot[21332]: go-librespot daemon starting... Aug 28 21:04:06 spla-repro go-librespot[21333]: time="2026-08-28T21:04:06+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:06 spla-repro go-librespot[21333]: time="2026-08-28T21:04:06+02:00" level=debug msg="app state loaded" Aug 28 21:04:06 spla-repro volumio[20938]: info: Updating MyVolumio device info Aug 28 21:04:06 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:06 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:06 spla-repro volumio[20938]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:06 spla-repro go-librespot[21333]: time="2026-08-28T21:04:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+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 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+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 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+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 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=info msg="zeroconf server listening on port 40249" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:07 spla-repro volumio[20938]: info: Successfully Updated MyVolumio device Aug 28 21:04:07 spla-repro volumio[20938]: info: Initializing connection to go-librespot Websocket Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=debug msg="new websocket client" Aug 28 21:04:07 spla-repro volumio[20938]: info: Connection to go-librespot Websocket established Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=debug msg="obtained new client token: AAEWSzB15u1ZPF3rSpNOgWCp1ck2ePRudHvY0d7Ma9jNaxpZDPTnlJCvZK1HXQqSaJdpj9gnyIwB+B6fgygFEl0Bai6mm5p010FwMTZ6fx4OdbEo2UwdApAzJfM8KEThFfzofFnljzVr4inHyfY531UHGBvAPvECZF/C9EX5EqsE6wj/Z/ad+1RS0ctl0jLP/MOsneDJkvMmunZtYshnDM3+C7WgMvaXVxcZUocLe9gslp9q2q1fevg=" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=debug msg="completed challenge" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:07 spla-repro go-librespot[21333]: time="2026-08-28T21:04:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:07 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:07 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:07 spla-repro volumio[20938]: info: Connection to go-librespot Websocket closed Aug 28 21:04:08 spla-repro volumio[20938]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:08 spla-repro volumio[20938]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:08 spla-repro volumio[20938]: info: Listing playlists Aug 28 21:04:08 spla-repro volumio[20938]: info: Listing playlists Aug 28 21:04:10 spla-repro volumio[20938]: info: Getting Spotify volume Aug 28 21:04:10 spla-repro volumio[20938]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:04:10 spla-repro volumio[20938]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:04:10 spla-repro volumio[20938]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 21:04:10 spla-repro volumio[20938]: errno: -111, Aug 28 21:04:10 spla-repro volumio[20938]: code: 'ECONNREFUSED', Aug 28 21:04:10 spla-repro volumio[20938]: syscall: 'connect', Aug 28 21:04:10 spla-repro volumio[20938]: address: '127.0.0.1', Aug 28 21:04:10 spla-repro volumio[20938]: port: 9879, Aug 28 21:04:10 spla-repro volumio[20938]: response: undefined Aug 28 21:04:10 spla-repro volumio[20938]: } Aug 28 21:04:10 spla-repro volumio[20938]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:04:10 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Aug 28 21:04:10 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:10 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:10 spla-repro go-librespot[21354]: go-librespot daemon starting... Aug 28 21:04:10 spla-repro go-librespot[21355]: time="2026-08-28T21:04:10+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:10 spla-repro go-librespot[21355]: time="2026-08-28T21:04:10+02:00" level=debug msg="app state loaded" Aug 28 21:04:10 spla-repro go-librespot[21355]: time="2026-08-28T21:04:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:11 spla-repro sudo[21379]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:11 spla-repro sudo[21379]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 21:03' Aug 28 21:04:11 spla-repro sudo[21379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+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 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+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 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+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 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=info msg="zeroconf server listening on port 45243" Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:11 spla-repro sudo[21379]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=debug msg="obtained new client token: AAFjXwyvty/0TaEVz5viksF0NTY91/g+QHAKIKXyXP/PQdMcjYwh9ODiMnsNKdBy1vEXk1lVwxFqCPMayO2V7e0eS+qjglX5GSZP3u7IzLbPAHXmlPiqh4IjLadZQ06DdDx74o8bxUX0qBkC9cyQDfM3Ex2i1YDC3pK/Nf9i2GvtzKk1Do+brO78sQKLNbj60KCfhNC265Dkus955w+GHnleRsM4SlepgwykTI+aWzXmCkTbW+0rAWfqtQ==" Aug 28 21:04:11 spla-repro volumio[20938]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:11 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 28 21:04:11 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 28 21:04:11 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:11 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:11.375+02:00 level=ERROR msg="failed reading message" error="read tcp 127.0.0.1:53574->127.0.0.1:3000: read: connection reset by peer" Aug 28 21:04:11 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:11.382+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:04:11 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=debug msg="completed challenge" Aug 28 21:04:11 spla-repro systemd[1]: volumio.service: Consumed 33.638s CPU time. Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04:11+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:11 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:04:11 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:04:11 spla-repro go-librespot[21355]: time="2026-08-28T21:04: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 28 21:04:11 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10775. Aug 28 21:04:11 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:11 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:11 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:04:11 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 28 21:04:11 spla-repro systemd[1]: volumio.service: Consumed 33.638s CPU time. Aug 28 21:04:11 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 28 21:04:11 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:04:12 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:12.386+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:04:13 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:13 spla-repro volumio[21393]: info: ----- Volumio3 ---- Aug 28 21:04:13 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:13 spla-repro volumio[21393]: info: ----- System startup ---- Aug 28 21:04:13 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:14 spla-repro volumio[21393]: info: MYVOLUMIO Environment detected Aug 28 21:04:14 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Aug 28 21:04:14 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:14 spla-repro volumio[21393]: info: Plugin folders cleanup Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning into folder /volumio/app/plugins/ Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category audio_interface Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category miscellanea Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category music_service Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category plugins.json Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category system_controller Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category user_interface Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning into folder /data/plugins/ Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category audio_interface Aug 28 21:04:14 spla-repro volumio[21393]: info: Scanning category music_service Aug 28 21:04:14 spla-repro volumio[21393]: info: Plugin folders cleanup completed Aug 28 21:04:14 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:14 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:14 spla-repro volumio[21393]: info: ----- Core plugins startup ---- Aug 28 21:04:14 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:14 spla-repro volumio[21393]: info: Loading plugins from folder /volumio/app/plugins/ Aug 28 21:04:14 spla-repro go-librespot[21418]: go-librespot daemon starting... Aug 28 21:04:14 spla-repro volumio[21393]: info: Adding plugin upnp to MyMusic Plugins Aug 28 21:04:14 spla-repro volumio[21393]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 28 21:04:14 spla-repro volumio[21393]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 28 21:04:14 spla-repro volumio[21393]: info: Loading plugins from folder /data/plugins/ Aug 28 21:04:14 spla-repro volumio[21393]: info: Loading plugin "system"... Aug 28 21:04:14 spla-repro go-librespot[21419]: time="2026-08-28T21:04:14+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:14 spla-repro go-librespot[21419]: time="2026-08-28T21:04:14+02:00" level=debug msg="app state loaded" Aug 28 21:04:14 spla-repro go-librespot[21419]: time="2026-08-28T21:04:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:14 spla-repro volumio[21393]: info: Loading plugin "appearance"... Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+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 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+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 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=info msg="zeroconf server listening on port 46549" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=debug msg="obtained new client token: AAFpqnPcgzRKeQQYiPG6eszHMBHvMXA8B252FQ5tHJPTRAg245+bD1mNQSPNa5+LR3ZJSUjVQun+XCmIehrBBJtdL+biZNWb9CELZjJ/CNHx4/q0UgpHa120F4WqvT/M4WqJi/csr9uQJxx4hWa4Y4DSMTNnpTPeE6JSqiQWUnPvqyIvhPEqUoAuevI0UyTJffAAwwbQL+AYRP/x+PHzGWfFD4G+/ZtW2tebS9G7YA1tDnQyg5yc1Qko/w==" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=debug msg="completed challenge" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04:15+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:15 spla-repro go-librespot[21419]: time="2026-08-28T21:04: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 28 21:04:15 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:15 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "network"... Aug 28 21:04:16 spla-repro volumio[21393]: info: Refreshing Cached IP Addresses Aug 28 21:04:16 spla-repro sudo[21433]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:16 spla-repro sudo[21435]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:16 spla-repro sudo[21433]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:04:16 spla-repro sudo[21433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:16 spla-repro sudo[21435]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:04:16 spla-repro sudo[21435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:16 spla-repro sudo[21433]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "services"... Aug 28 21:04:16 spla-repro sudo[21435]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "volumio5onboarding"... Aug 28 21:04:16 spla-repro sudo[21443]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:16 spla-repro sudo[21443]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 28 21:04:16 spla-repro sudo[21443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "alsa_controller"... Aug 28 21:04:16 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "wizard"... Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "networkfs"... Aug 28 21:04:16 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:16] [connect] Successful connection Aug 28 21:04:16 spla-repro volumio[21393]: info: Starting Udev Watcher for removable devices Aug 28 21:04:16 spla-repro volumio[21393]: info: Ignoring mount for partition: boot Aug 28 21:04:16 spla-repro volumio[21393]: info: Ignoring mount for partition: volumio Aug 28 21:04:16 spla-repro volumio[21393]: info: Ignoring mount for partition: volumio_data Aug 28 21:04:16 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "volumio_command_line_client"... Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "upnp"... Aug 28 21:04:16 spla-repro volumio[21393]: info: [1787943856437] Starting Upmpd Daemon Aug 28 21:04:16 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "my_music"... Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "mpd"... Aug 28 21:04:16 spla-repro volumio[21393]: info: Loading plugin "upnp_browser"... Aug 28 21:04:16 spla-repro sudo[21443]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:18 spla-repro volumio[21393]: info: Starting UPNP Browser Aug 28 21:04:18 spla-repro volumio[21393]: info: Loading plugin "alarm-clock"... Aug 28 21:04:18 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Aug 28 21:04:18 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:18 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:18 spla-repro go-librespot[21466]: go-librespot daemon starting... Aug 28 21:04:18 spla-repro go-librespot[21467]: time="2026-08-28T21:04:18+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:18 spla-repro go-librespot[21467]: time="2026-08-28T21:04:18+02:00" level=debug msg="app state loaded" Aug 28 21:04:18 spla-repro go-librespot[21467]: time="2026-08-28T21:04:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:18 spla-repro volumio[21393]: info: Loading plugin "airplay_emulation"... Aug 28 21:04:18 spla-repro volumio[21393]: info: Starting Shairport Sync Aug 28 21:04:18 spla-repro volumio[21393]: info: Loading plugin "last_100"... Aug 28 21:04:18 spla-repro volumio[21393]: info: Loading plugin "webradio"... Aug 28 21:04:19 spla-repro volumio[21393]: info: Loading plugin "i2s_dacs"... Aug 28 21:04:19 spla-repro volumio[21393]: info: Loading plugin "volumiodiscovery"... Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** For more information see Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:19 spla-repro volumio[21393]: *** WARNING *** For more information see Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** For more information see Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:19 spla-repro node[21393]: *** WARNING *** For more information see Aug 28 21:04:19 spla-repro volumio[21393]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 21:04:19 spla-repro volumio[21393]: info: Discovery: Started advertising with name: Spálňa-repro Aug 28 21:04:19 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:19 spla-repro volumio[21393]: info: Loading plugin "spop"... Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04: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 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04: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 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04: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 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=info msg="zeroconf server listening on port 38531" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=debug msg="obtained new client token: AAErhOkO428lJcT0TqNLJx26iTh0AZoBUdcrcpLfCACNL7+GusWB914eMsSIsAhPTCpbT+4mOX1Tsgxr3nSgx9AIEPM2hK3Qci3qcs9Uu4xzOlGC9EII/JXt71tn7OlxhCn3ImLfEg5+2eNCnDZMy40nMnwxXNFv2A4lmxhYQ3jgDhJEHZULTaRTfnYzVUQ+9laM8Gp/Obw+NECU3mBRyrzIa7gRxC1xGfPj0jp0Sfxos7CFKWDOLcs1ag==" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=debug msg="completed challenge" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:19 spla-repro go-librespot[21467]: time="2026-08-28T21:04:19+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:19 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:19 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "outputs"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "albumart"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Plugin example_plugin is not enabled Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "inputs"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "updater_comm"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Plugin mpdemulation is not enabled Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "rest_api"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading plugin "websocket"... Aug 28 21:04:20 spla-repro volumio[21393]: info: Starting Socket.io Server version 1.7.4 Aug 28 21:04:20 spla-repro volumio[21393]: info: Plugin fusiondsp is not enabled Aug 28 21:04:20 spla-repro volumio[21393]: info: Loading i18n strings for locale sk Aug 28 21:04:20 spla-repro volumio[21393]: Updating browse sources language Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::initPlayerControls Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:20 spla-repro volumio[21393]: Express server listening on port 3000 Aug 28 21:04:20 spla-repro volumio[21393]: [Metrics] WebUI: 7s 691.31ms Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreStateMachine::resetVolumioState Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreStateMachine::getcurrentVolume Aug 28 21:04:20 spla-repro volumio[21393]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:04:20 spla-repro volumio[21393]: info: Cannot read play queue from file Aug 28 21:04:21 spla-repro volumio[21393]: info: Volumio Network Manager: Network status updated: 1 Aug 28 21:04:21 spla-repro volumio[21393]: 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 28 21:04:21 spla-repro volumio[21393]: Unable to parse: Aug 28 21:04:21 spla-repro volumio[21393]: Simple mixer control 'Master',0 Aug 28 21:04:21 spla-repro volumio[21393]: Capabilities: volume volume-joined Aug 28 21:04:21 spla-repro volumio[21393]: Playback channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Capture channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Limits: 0 - 248 Aug 28 21:04:21 spla-repro volumio[21393]: Mono: 112 [45%] Aug 28 21:04:21 spla-repro volumio[21393]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:04:21 spla-repro volumio[21479]: Forking 3 albumart workers Aug 28 21:04:21 spla-repro volumio[21393]: 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 28 21:04:21 spla-repro volumio[21393]: info: Received Get System Info Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: Getting this device information Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 21:04:21 spla-repro volumio[21393]: 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 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 21:04:21 spla-repro volumio[21393]: 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 28 21:04:21 spla-repro volumio[21393]: Unable to parse: Aug 28 21:04:21 spla-repro volumio[21393]: Simple mixer control 'Master',0 Aug 28 21:04:21 spla-repro volumio[21393]: Capabilities: volume volume-joined Aug 28 21:04:21 spla-repro volumio[21393]: Playback channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Capture channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Limits: 0 - 248 Aug 28 21:04:21 spla-repro volumio[21393]: Mono: 112 [45%] Aug 28 21:04:21 spla-repro volumio[21393]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::pushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::updateTrackBlock Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrackBlock Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::setRepeat null single undefined Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::pushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::setRandom null Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::pushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:21 spla-repro volumio[21393]: info: Setting Device type: Raspberry PI Aug 28 21:04:21 spla-repro volumio[21393]: info: Completed loading Core Plugins Aug 28 21:04:21 spla-repro volumio[21393]: info: Preparing to generate the ALSA configuration file Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: Found device kuchyna-repro Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 28 21:04:21 spla-repro volumio[21393]: Unable to parse: Aug 28 21:04:21 spla-repro volumio[21393]: Simple mixer control 'Master',0 Aug 28 21:04:21 spla-repro volumio[21393]: Capabilities: volume volume-joined Aug 28 21:04:21 spla-repro volumio[21393]: Playback channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Capture channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Limits: 0 - 248 Aug 28 21:04:21 spla-repro volumio[21393]: Mono: 112 [45%] Aug 28 21:04:21 spla-repro volumio[21393]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: 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 28 21:04:21 spla-repro volumio[21393]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: Found device kupelna-repro Aug 28 21:04:21 spla-repro volumio[21393]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 28 21:04:21 spla-repro volumio[21393]: 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: 5 Aug 28 21:04:21 spla-repro volumio[21393]: Unable to parse: Aug 28 21:04:21 spla-repro volumio[21393]: Simple mixer control 'Master',0 Aug 28 21:04:21 spla-repro volumio[21393]: Capabilities: volume volume-joined Aug 28 21:04:21 spla-repro volumio[21393]: Playback channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Capture channels: Mono Aug 28 21:04:21 spla-repro volumio[21393]: Limits: 0 - 248 Aug 28 21:04:21 spla-repro volumio[21393]: Mono: 112 [45%] Aug 28 21:04:21 spla-repro volumio[21393]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreStateMachine::pushState Aug 28 21:04:21 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:21 spla-repro volumio[21393]: info: Asound.conf file unchanged, so no further update is needed Aug 28 21:04:21 spla-repro volumio[21393]: info: Output device has changed, restarting MPD Aug 28 21:04:21 spla-repro volumio[21393]: info: Output device has changed, restarting Shairport Sync Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:21 spla-repro sudo[21535]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:21 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:21 spla-repro sudo[21537]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro sudo[21537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:04:22 spla-repro sudo[21537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:22 spla-repro sudo[21535]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:04:22 spla-repro sudo[21535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:22 spla-repro sudo[21535]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:22 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 28 21:04:22 spla-repro volumio[21393]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:22 spla-repro volumio[21393]: info: ___________ START PLUGINS ___________ Aug 28 21:04:22 spla-repro volumio[21393]: info: ControllerMpd::onStart: Initializing MPD Aug 28 21:04:22 spla-repro volumio[21393]: info: Creating MPD Configuration file Aug 28 21:04:22 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:04:22 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:04:22 spla-repro systemd[1]: mpd.service: Consumed 5.739s CPU time. Aug 28 21:04:22 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:04:22 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:04:22 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:22 spla-repro volumio[21393]: info: [1787943862220] CoreMusicLibrary::Adding element Mediálne servery Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:22 spla-repro sudo[21547]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro sudo[21545]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:04:22 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:04:22 spla-repro sudo[21545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 21:04:22 spla-repro sudo[21547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:04:22 spla-repro sudo[21547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:22 spla-repro sudo[21545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:22 spla-repro sudo[21547]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:22 spla-repro sudo[21550]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro volumio[21393]: info: UPNP Browser: Client initialized successfully Aug 28 21:04:22 spla-repro sudo[21550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:04:22 spla-repro sudo[21545]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:22 spla-repro sudo[21550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:22 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:22.393+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 21:04:22 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:04:22 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:04:22 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:04:22 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:04:22 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:04:22 spla-repro volumio[21393]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:22 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:04:22 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:04:22 spla-repro volumio[21393]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:22 spla-repro volumio[21393]: info: [1787943862569] CoreMusicLibrary::Adding element Last_100 Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:22 spla-repro volumio[21393]: info: [1787943862575] CoreMusicLibrary::Adding element Webradio Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:22 spla-repro volumio[21393]: info: Initializing BBC Radios Aug 28 21:04:22 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Aug 28 21:04:22 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:22 spla-repro go-librespot[21578]: go-librespot daemon starting... Aug 28 21:04:22 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:22 spla-repro volumio[21393]: info: Creating Spotify config file Aug 28 21:04:22 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:22 spla-repro go-librespot[21579]: time="2026-08-28T21:04:22+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:22 spla-repro sudo[21564]: root : unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro sudo[21564]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:22 spla-repro sudo[21564]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 21:04:22 spla-repro sudo[21564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 21:04:22 spla-repro sudo[21564]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:23 spla-repro go-librespot[21579]: time="2026-08-28T21:04:23+02:00" level=info msg="zeroconf server listening on port 38077" Aug 28 21:04:23 spla-repro go-librespot[21579]: time="2026-08-28T21:04:23+02:00" level=info msg="using built-in mDNS responder" Aug 28 21:04:23 spla-repro volumio[21393]: info: Volumio Calling Home Aug 28 21:04:23 spla-repro volumio[21498]: Starting albumart workers Aug 28 21:04:23 spla-repro volumio[21496]: Starting albumart workers Aug 28 21:04:24 spla-repro volumio[21497]: Starting albumart workers Aug 28 21:04:24 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:04:24 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:24 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:24 spla-repro volumio[21393]: info: Discovery: Connected to remote: 192.168.200.201 Aug 28 21:04:24 spla-repro volumio[21393]: info: MPD Permissions set Aug 28 21:04:24 spla-repro volumio[21393]: info: MPD Permissions set Aug 28 21:04:24 spla-repro volumio[21393]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:04:24 spla-repro volumio[21393]: info: Discovery: Found device Spálňa-repro Aug 28 21:04:24 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:24 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:25 spla-repro volumio[21393]: info: Discovery: Connected to remote: 192.168.200.202 Aug 28 21:04:25 spla-repro volumio[21393]: info: Volumio called home Aug 28 21:04:25 spla-repro volumio[21393]: info: Spotify config file written Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:25 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:25 spla-repro sudo[21601]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:25 spla-repro sudo[21601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 21:04:25 spla-repro sudo[21601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:25 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 28 21:04:25 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 28 21:04:25 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:25 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:25 spla-repro go-librespot[21603]: go-librespot daemon starting... Aug 28 21:04:25 spla-repro sudo[21601]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:25 spla-repro go-librespot[21607]: time="2026-08-28T21:04:25+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:25 spla-repro go-librespot[21607]: time="2026-08-28T21:04:25+02:00" level=debug msg="app state loaded" Aug 28 21:04:25 spla-repro go-librespot[21607]: time="2026-08-28T21:04:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:25 spla-repro volumio[21393]: 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 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:25 spla-repro volumio[21393]: info: No need to fix Spotify hosts Aug 28 21:04:25 spla-repro volumio[21393]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:04:25 spla-repro volumio[21393]: info: Discovery: Found device Spálňa-repro Aug 28 21:04:25 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:25 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+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 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+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 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=info msg="zeroconf server listening on port 33457" Aug 28 21:04:26 spla-repro volumio[21393]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 28 21:04:26 spla-repro volumio[21393]: info: Starting Shairport Sync Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:26 spla-repro volumio[21393]: info: Starting Shairport Sync Aug 28 21:04:26 spla-repro volumio[21393]: info: Starting Shairport Sync Aug 28 21:04:26 spla-repro sudo[21636]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro sudo[21636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:26 spla-repro sudo[21636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro sudo[21638]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro sudo[21638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:26 spla-repro sudo[21638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro sudo[21641]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro sudo[21641]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:26 spla-repro sudo[21641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=debug msg="obtained new client token: AAFyLY9qatmEHCLCetVM6Upk3jxa5CSmWj090KSTWhfkmYw0G1Ggo+qsVwB9Niluk0PuKdCQGKiW4W6vVLLWq2r6ZVC44+d79dibUdiY5Yyv/+l61BaLy2kJLfjuy/suTa7omGpvCGtz0sqzJanrSjpQ8gKeOnYjB4NNpLpoglNX1XXIrm+dm3MfhZ1BbpN41y3f2qsWJIQ0k7MWuJSIWIX3rkf3DBTwi9eq0TeWbhngyYKCZ/JgiSvrIw==" Aug 28 21:04:26 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:26 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:26 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 21:04:26 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 21:04:26 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:26 spla-repro systemd[1]: shairport-sync.service: Consumed 2.009s CPU time. Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:26 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=debug msg="completed challenge" Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04:26+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:26 spla-repro sudo[21636]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro sudo[21662]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro sudo[21638]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro sudo[21660]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro volumio[21393]: info: Shairport-Sync Started Aug 28 21:04:26 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 21:04:26 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 21:04:26 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:26 spla-repro sudo[21662]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:04:26 spla-repro volumio[21393]: Error adding Membership: Error: addMembership EINVAL Aug 28 21:04:26 spla-repro volumio[21393]: info: Shairport-Sync Started Aug 28 21:04:26 spla-repro sudo[21662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro sudo[21660]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:04:26 spla-repro sudo[21660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:26 spla-repro sudo[21660]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro sudo[21641]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro sudo[21662]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro volumio[21393]: info: Shairport-Sync Started Aug 28 21:04:26 spla-repro go-librespot[21607]: time="2026-08-28T21:04: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 28 21:04:26 spla-repro sudo[21670]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:26 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:26 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:26 spla-repro sudo[21670]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 21:04:26 spla-repro sudo[21670]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:26 spla-repro sudo[21670]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:26 spla-repro volumio[21393]: info: Upmpdcli Daemon Started Aug 28 21:04:28 spla-repro volumio[21393]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:28 spla-repro volumio[21393]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:28 spla-repro volumio[21393]: info: Listing playlists Aug 28 21:04:28 spla-repro volumio[21393]: info: Listing playlists Aug 28 21:04:28 spla-repro mpd[21586]: 2026-08-28T21:04:28 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 21:04:28 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 21:04:28 spla-repro sudo[21550]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:28 spla-repro sudo[21537]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:28 spla-repro volumio[21393]: info: Completed starting Core Plugins Aug 28 21:04:28 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:28 spla-repro volumio[21393]: info: ----- MyVolumio plugins startup ---- Aug 28 21:04:28 spla-repro volumio[21393]: info: ------------------------------------------- Aug 28 21:04:28 spla-repro volumio[21393]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 21:04:28 spla-repro volumio[21393]: error: MPD error: The expression evaluated to a falsy value: Aug 28 21:04:28 spla-repro volumio[21393]: assert.ok(self.idling) Aug 28 21:04:28 spla-repro volumio[21393]: error: The expression evaluated to a falsy value: Aug 28 21:04:28 spla-repro volumio[21393]: assert.ok(self.idling) Aug 28 21:04:28 spla-repro volumio[21393]: error: updateQueue error: null Aug 28 21:04:28 spla-repro volumio[21393]: info: MPD running with PID21586 Aug 28 21:04:28 spla-repro volumio[21393]: ,establishing connection Aug 28 21:04:28 spla-repro volumio[21393]: error: updateQueue error: null Aug 28 21:04:28 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:28] [connect] Successful connection Aug 28 21:04:28 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:28] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787943868 101 Aug 28 21:04:28 spla-repro volumio[21393]: 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 28 21:04:29 spla-repro volumio[21393]: info: go-librespot daemon successfully initialized Aug 28 21:04:29 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 21:04:29 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:30 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:30 spla-repro go-librespot[21690]: go-librespot daemon starting... Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=debug msg="app state loaded" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+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 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+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 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=info msg="zeroconf server listening on port 42977" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=debug msg="obtained new client token: AAENDLxI0if/LW0KJMn1xeGmL+Jb8aE8DcReG4yrZyFJcN2anl43reL8dlPVS/0lzNJWV/zIlM1a8DzBx+PeSQHDLkjQBg4XQxdjI/BrmFN21FXBvfBFJ2xjvoihZbTbts7r4wbeCssTA2ongBG6bi3w4kmnrDnQHOPdWSeCbevtiF3n32TVz32SsYgTImRPfJQpKZoKkHoyn9x61rkwGIx97+Y47w6WwLLy1+0tGvtY++cFjV+aPq/wBw==" Aug 28 21:04:30 spla-repro go-librespot[21691]: time="2026-08-28T21:04:30+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:32 spla-repro volumio[21393]: info: Initializing connection to go-librespot Websocket Aug 28 21:04:32 spla-repro go-librespot[21691]: time="2026-08-28T21:04:32+02:00" level=debug msg="new websocket client" Aug 28 21:04:32 spla-repro volumio[21393]: info: Connection to go-librespot Websocket established Aug 28 21:04:33 spla-repro go-librespot[21691]: time="2026-08-28T21:04:33+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:33 spla-repro go-librespot[21691]: time="2026-08-28T21:04:33+02:00" level=debug msg="completed challenge" Aug 28 21:04:33 spla-repro go-librespot[21691]: time="2026-08-28T21:04:33+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:33 spla-repro go-librespot[21691]: time="2026-08-28T21:04: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 28 21:04:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:33 spla-repro volumio[21393]: info: Connection to go-librespot Websocket closed Aug 28 21:04:33 spla-repro volumio[21393]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 21:04:35 spla-repro volumio[21393]: info: Getting Spotify volume Aug 28 21:04:35 spla-repro volumio[21393]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:04:35 spla-repro volumio[21393]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:04:35 spla-repro volumio[21393]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 21:04:35 spla-repro volumio[21393]: errno: -111, Aug 28 21:04:35 spla-repro volumio[21393]: code: 'ECONNREFUSED', Aug 28 21:04:35 spla-repro volumio[21393]: syscall: 'connect', Aug 28 21:04:35 spla-repro volumio[21393]: address: '127.0.0.1', Aug 28 21:04:35 spla-repro volumio[21393]: port: 9879, Aug 28 21:04:35 spla-repro volumio[21393]: response: undefined Aug 28 21:04:35 spla-repro volumio[21393]: } Aug 28 21:04:35 spla-repro volumio[21393]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:04:35 spla-repro sudo[21716]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:35 spla-repro sudo[21716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 21:03' Aug 28 21:04:35 spla-repro sudo[21716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:36 spla-repro sudo[21716]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:36 spla-repro volumio[21393]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:36 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:36.284+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 28 21:04:36 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:36.289+02:00 level=WARN msg="reconnection attempt failed" error="read tcp 127.0.0.1:35744->127.0.0.1:3000: read: connection reset by peer" Aug 28 21:04:36 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:36] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 28 21:04:36 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:36] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 28 21:04:36 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:36 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 28 21:04:36 spla-repro systemd[1]: volumio.service: Consumed 29.071s CPU time. Aug 28 21:04:36 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 21:04:36 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:04:36 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:36 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:36 spla-repro go-librespot[21741]: go-librespot daemon starting... Aug 28 21:04:36 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:04:36 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10776. Aug 28 21:04:36 spla-repro systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 28 21:04:36 spla-repro systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 28 21:04:36 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:04:36 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 28 21:04:36 spla-repro systemd[1]: volumio.service: Consumed 29.071s CPU time. Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=debug msg="app state loaded" Aug 28 21:04:36 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 28 21:04:36 spla-repro systemd[1]: welcome.service: Deactivated successfully. Aug 28 21:04:36 spla-repro systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 28 21:04:36 spla-repro systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 28 21:04:36 spla-repro systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 28 21:04:36 spla-repro welcome[21757]: Resolved ip:[1] 192.168.200.203 Aug 28 21:04:36 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:36 spla-repro systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 28 21:04:36 spla-repro systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+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 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+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 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+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 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=info msg="zeroconf server listening on port 40805" Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:36 spla-repro go-librespot[21745]: time="2026-08-28T21:04:36+02:00" level=debug msg="obtained new client token: AAHZUEjCEI6LOA0Ih7Q7uCvk+ofUq1NFmeX+2vZee+dSZPm7Xgou3/QGrjwNR2tEJtFCNW70k96lSaUF6XMoppVCdvecyAeUedbuodNtXh9/4qfbZ4VPEFuf2upJp/UGRnDLSDPAzdmoZlVMwZs3EXv2t9hSJfUR0baiGlcIGbC2xm5ipLPYZGwTgn1ZDkqA4VJllXnqkISu0/5Qvxa/oz5fuhoM7b+F8JyOueabLZKuuahliWPo+i8qFA==" Aug 28 21:04:37 spla-repro go-librespot[21745]: time="2026-08-28T21:04:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:37 spla-repro go-librespot[21745]: time="2026-08-28T21:04:37+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:37 spla-repro go-librespot[21745]: time="2026-08-28T21:04:37+02:00" level=debug msg="completed challenge" Aug 28 21:04:37 spla-repro go-librespot[21745]: time="2026-08-28T21:04:37+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:37 spla-repro go-librespot[21745]: time="2026-08-28T21:04:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:37 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:37 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:37 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:37.291+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:04:38 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:38 spla-repro volumio[21754]: info: ----- Volumio3 ---- Aug 28 21:04:38 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:38 spla-repro volumio[21754]: info: ----- System startup ---- Aug 28 21:04:38 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:39 spla-repro volumio[21754]: info: MYVOLUMIO Environment detected Aug 28 21:04:39 spla-repro volumio[21754]: info: Plugin folders cleanup Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning into folder /volumio/app/plugins/ Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category audio_interface Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category miscellanea Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category music_service Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category plugins.json Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category system_controller Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category user_interface Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning into folder /data/plugins/ Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category audio_interface Aug 28 21:04:39 spla-repro volumio[21754]: info: Scanning category music_service Aug 28 21:04:39 spla-repro volumio[21754]: info: Plugin folders cleanup completed Aug 28 21:04:39 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:39 spla-repro volumio[21754]: info: ----- Core plugins startup ---- Aug 28 21:04:39 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:39 spla-repro volumio[21754]: info: Loading plugins from folder /volumio/app/plugins/ Aug 28 21:04:39 spla-repro volumio[21754]: info: Adding plugin upnp to MyMusic Plugins Aug 28 21:04:39 spla-repro volumio[21754]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 28 21:04:39 spla-repro volumio[21754]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 28 21:04:39 spla-repro volumio[21754]: info: Loading plugins from folder /data/plugins/ Aug 28 21:04:39 spla-repro volumio[21754]: info: Loading plugin "system"... Aug 28 21:04:39 spla-repro volumio[21754]: info: Loading plugin "appearance"... Aug 28 21:04:40 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 21:04:40 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:40 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:40 spla-repro go-librespot[21789]: go-librespot daemon starting... Aug 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+02:00" level=debug msg="app state loaded" Aug 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+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 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+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 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+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 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+02:00" level=info msg="zeroconf server listening on port 36063" Aug 28 21:04:40 spla-repro go-librespot[21790]: time="2026-08-28T21:04:40+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=debug msg="obtained new client token: AAF5lUctPlQTekgKp4fAfnAU+BamKV9lrjUUiupmRc15mnzc9IWAI3sW0epEIvke2QmH8fiPnaJadh+hANW4Uo/Pb80OUkVNZdh75/vJAT54AI6pjFMEkd49nF5hw1Moe0Zo6IT8iqEy+ZWWnfyPxeQF6WR+Y2zCtA0WITu3wgTzz5FCbm8kZ5+a/Y4CBMaPCWrnYbl099J/rB/3y+m9g36Hyvhsp/lsc8vglKzqo73Xw5piDWrVVjc=" Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "network"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Refreshing Cached IP Addresses Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:41 spla-repro sudo[21801]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:41 spla-repro sudo[21803]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:41 spla-repro sudo[21801]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:04:41 spla-repro sudo[21801]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:41 spla-repro sudo[21803]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:04:41 spla-repro sudo[21803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "services"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "volumio5onboarding"... Aug 28 21:04:41 spla-repro sudo[21803]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:41 spla-repro sudo[21801]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:41 spla-repro sudo[21810]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "alsa_controller"... Aug 28 21:04:41 spla-repro sudo[21810]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 28 21:04:41 spla-repro sudo[21810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:41 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:41] [connect] Successful connection Aug 28 21:04:41 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "wizard"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "networkfs"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Starting Udev Watcher for removable devices Aug 28 21:04:41 spla-repro volumio[21754]: info: Ignoring mount for partition: boot Aug 28 21:04:41 spla-repro volumio[21754]: info: Ignoring mount for partition: volumio Aug 28 21:04:41 spla-repro volumio[21754]: info: Ignoring mount for partition: volumio_data Aug 28 21:04:41 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "volumio_command_line_client"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "upnp"... Aug 28 21:04:41 spla-repro volumio[21754]: info: [1787943881451] Starting Upmpd Daemon Aug 28 21:04:41 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "my_music"... Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "mpd"... Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=debug msg="completed challenge" Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:41 spla-repro go-librespot[21790]: time="2026-08-28T21:04:41+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:41 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:41 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:41 spla-repro volumio[21754]: info: Loading plugin "upnp_browser"... Aug 28 21:04:41 spla-repro sudo[21810]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:43 spla-repro volumio[21754]: info: Starting UPNP Browser Aug 28 21:04:43 spla-repro volumio[21754]: info: Loading plugin "alarm-clock"... Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "airplay_emulation"... Aug 28 21:04:44 spla-repro volumio[21754]: info: Starting Shairport Sync Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "last_100"... Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "webradio"... Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "i2s_dacs"... Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "volumiodiscovery"... Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** For more information see Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:44 spla-repro volumio[21754]: *** WARNING *** For more information see Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** For more information see Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:04:44 spla-repro node[21754]: *** WARNING *** For more information see Aug 28 21:04:44 spla-repro volumio[21754]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 21:04:44 spla-repro volumio[21754]: info: Discovery: Started advertising with name: Spálňa-repro Aug 28 21:04:44 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:04:44 spla-repro volumio[21754]: info: Loading plugin "spop"... Aug 28 21:04:44 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 21:04:44 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:44 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:44 spla-repro go-librespot[21836]: go-librespot daemon starting... Aug 28 21:04:44 spla-repro go-librespot[21837]: time="2026-08-28T21:04:44+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:44 spla-repro go-librespot[21837]: time="2026-08-28T21:04:44+02:00" level=debug msg="app state loaded" Aug 28 21:04:44 spla-repro go-librespot[21837]: time="2026-08-28T21:04:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+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 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+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 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+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 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=info msg="zeroconf server listening on port 39465" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=debug msg="obtained new client token: AAG6F6hEx+dXd8l3Uj1v/ZpwF/l58qA3CTVuFyRraT6t+F19sle2KGKeOtFgLyvCL+1APuEuQCh7ugPOXH6zXMTCa2RTxM62RcHf1fX6FBkq98a7rLCd1H3rq4jMzZ3YqKF7oD/vqk/LYEaYnwOkKQrKzB7OfeVW9KCBOPLX21V8NMtO9BkK1d/9PJ5dgolwJanlPovtO0Sg9hOo70oM2Aq2aVVidTM9yqCRC2Q0IFeuRIke77PD+25Bug==" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=debug msg="completed challenge" Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "outputs"... Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "albumart"... Aug 28 21:04:45 spla-repro volumio[21754]: info: Plugin example_plugin is not enabled Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "inputs"... Aug 28 21:04:45 spla-repro go-librespot[21837]: time="2026-08-28T21:04:45+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:45 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:45 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "updater_comm"... Aug 28 21:04:45 spla-repro volumio[21754]: info: Plugin mpdemulation is not enabled Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "rest_api"... Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading plugin "websocket"... Aug 28 21:04:45 spla-repro volumio[21754]: info: Starting Socket.io Server version 1.7.4 Aug 28 21:04:45 spla-repro volumio[21754]: info: Plugin fusiondsp is not enabled Aug 28 21:04:45 spla-repro volumio[21754]: info: Loading i18n strings for locale sk Aug 28 21:04:45 spla-repro volumio[21754]: Updating browse sources language Aug 28 21:04:45 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::initPlayerControls Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: Express server listening on port 3000 Aug 28 21:04:46 spla-repro volumio[21754]: [Metrics] WebUI: 7s 880.00ms Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::resetVolumioState Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::getcurrentVolume Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:04:46 spla-repro volumio[21754]: info: Cannot read play queue from file Aug 28 21:04:46 spla-repro volumio[21754]: info: Volumio Network Manager: Network status updated: 1 Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: Unable to parse: Aug 28 21:04:46 spla-repro volumio[21754]: Simple mixer control 'Master',0 Aug 28 21:04:46 spla-repro volumio[21754]: Capabilities: volume volume-joined Aug 28 21:04:46 spla-repro volumio[21754]: Playback channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Capture channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Limits: 0 - 248 Aug 28 21:04:46 spla-repro volumio[21754]: Mono: 112 [45%] Aug 28 21:04:46 spla-repro volumio[21754]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:04:46 spla-repro volumio[21846]: Forking 3 albumart workers Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: Unable to parse: Aug 28 21:04:46 spla-repro volumio[21754]: Simple mixer control 'Master',0 Aug 28 21:04:46 spla-repro volumio[21754]: Capabilities: volume volume-joined Aug 28 21:04:46 spla-repro volumio[21754]: Playback channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Capture channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Limits: 0 - 248 Aug 28 21:04:46 spla-repro volumio[21754]: Mono: 112 [45%] Aug 28 21:04:46 spla-repro volumio[21754]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::pushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::updateTrackBlock Aug 28 21:04:46 spla-repro volumio[21754]: info: CorePlayQueue::getTrackBlock Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::setRepeat null single undefined Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::pushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::setRandom null Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::pushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:46 spla-repro volumio[21754]: info: Setting Device type: Raspberry PI Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: info: Completed loading Core Plugins Aug 28 21:04:46 spla-repro volumio[21754]: info: Preparing to generate the ALSA configuration file Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: Unable to parse: Aug 28 21:04:46 spla-repro volumio[21754]: Simple mixer control 'Master',0 Aug 28 21:04:46 spla-repro volumio[21754]: Capabilities: volume volume-joined Aug 28 21:04:46 spla-repro volumio[21754]: Playback channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Capture channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Limits: 0 - 248 Aug 28 21:04:46 spla-repro volumio[21754]: Mono: 112 [45%] Aug 28 21:04:46 spla-repro volumio[21754]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: Found device kuchyna-repro Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 28 21:04:46 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:46.817+02:00 level=ERROR msg="failed to update discovery on Ethernet info change" error="failed to get system info: could not get system info: context deadline exceeded" Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: Found device kupelna-repro Aug 28 21:04:46 spla-repro volumio[21754]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 28 21:04:46 spla-repro volumio[21754]: 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 28 21:04:46 spla-repro volumio[21754]: Unable to parse: Aug 28 21:04:46 spla-repro volumio[21754]: Simple mixer control 'Master',0 Aug 28 21:04:46 spla-repro volumio[21754]: Capabilities: volume volume-joined Aug 28 21:04:46 spla-repro volumio[21754]: Playback channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Capture channels: Mono Aug 28 21:04:46 spla-repro volumio[21754]: Limits: 0 - 248 Aug 28 21:04:46 spla-repro volumio[21754]: Mono: 112 [45%] Aug 28 21:04:46 spla-repro volumio[21754]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreStateMachine::pushState Aug 28 21:04:46 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:46 spla-repro volumio[21754]: info: CoreCommandRouter::volumioPushState Aug 28 21:04:46 spla-repro volumio[21754]: 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: 6 Aug 28 21:04:46 spla-repro volumio[21754]: info: Asound.conf file unchanged, so no further update is needed Aug 28 21:04:46 spla-repro volumio[21754]: info: Output device has changed, restarting MPD Aug 28 21:04:47 spla-repro volumio[21754]: info: Output device has changed, restarting Shairport Sync Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:47 spla-repro sudo[21905]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:04:47 spla-repro sudo[21905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:47 spla-repro sudo[21905]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:47 spla-repro volumio[21754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:47 spla-repro volumio[21754]: info: ___________ START PLUGINS ___________ Aug 28 21:04:47 spla-repro sudo[21907]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:04:47 spla-repro sudo[21907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:47 spla-repro volumio[21754]: info: ControllerMpd::onStart: Initializing MPD Aug 28 21:04:47 spla-repro volumio[21754]: info: Creating MPD Configuration file Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:47 spla-repro volumio[21754]: info: [1787943887163] CoreMusicLibrary::Adding element Mediálne servery Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:47 spla-repro volumio[21754]: info: UPNP Browser: Client initialized successfully Aug 28 21:04:47 spla-repro sudo[21914]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 28 21:04:47 spla-repro sudo[21914]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 21:04:47 spla-repro sudo[21914]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:47 spla-repro sudo[21919]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21917]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21919]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:04:47 spla-repro sudo[21919]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:47 spla-repro sudo[21914]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:47 spla-repro sudo[21917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:04:47 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:04:47 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:47 spla-repro systemd[1]: mpd.service: Consumed 5.661s CPU time. Aug 28 21:04:47 spla-repro sudo[21917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:47 spla-repro sudo[21917]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:47 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:04:47 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:04:47 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:04:47 spla-repro volumio[21754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:47 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:04:47 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:04:47 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:04:47 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:04:47 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:04:47 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:04:47 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:04:47 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:04:47 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:04:47 spla-repro volumio[21754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:47 spla-repro volumio[21754]: info: [1787943887538] CoreMusicLibrary::Adding element Last_100 Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:04:47 spla-repro volumio[21754]: info: [1787943887548] CoreMusicLibrary::Adding element Webradio Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:47 spla-repro volumio[21754]: info: Initializing BBC Radios Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:47 spla-repro volumio[21754]: info: Creating Spotify config file Aug 28 21:04:47 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:47 spla-repro sudo[21935]: root : unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21935]: sudo: unable to resolve host spla-repro: System error Aug 28 21:04:47 spla-repro sudo[21935]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 21:04:47 spla-repro sudo[21935]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 21:04:47 spla-repro sudo[21935]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:48 spla-repro volumio[21754]: info: Volumio Calling Home Aug 28 21:04:48 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 21:04:48 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:48 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:48 spla-repro go-librespot[21954]: go-librespot daemon starting... Aug 28 21:04:48 spla-repro go-librespot[21955]: time="2026-08-28T21:04:48+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:49 spla-repro volumio[21863]: Starting albumart workers Aug 28 21:04:49 spla-repro volumio[21865]: Starting albumart workers Aug 28 21:04:49 spla-repro volumio[21754]: 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: 7 Aug 28 21:04:49 spla-repro volumio[21864]: Starting albumart workers Aug 28 21:04:49 spla-repro go-librespot[21955]: time="2026-08-28T21:04:49+02:00" level=info msg="zeroconf server listening on port 44101" Aug 28 21:04:49 spla-repro go-librespot[21955]: time="2026-08-28T21:04:49+02:00" level=info msg="using built-in mDNS responder" Aug 28 21:04:49 spla-repro volumio[21754]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:04:49 spla-repro volumio[21754]: info: Discovery: Found device Spálňa-repro Aug 28 21:04:49 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:49 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:49 spla-repro volumio[21754]: info: Discovery: Connected to remote: 192.168.200.201 Aug 28 21:04:49 spla-repro volumio[21754]: info: MPD Permissions set Aug 28 21:04:49 spla-repro volumio[21754]: info: MPD Permissions set Aug 28 21:04:49 spla-repro volumio[21754]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:04:49 spla-repro volumio[21754]: info: Discovery: Found device Spálňa-repro Aug 28 21:04:49 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:49 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:50 spla-repro volumio[21754]: info: Discovery: Connected to remote: 192.168.200.202 Aug 28 21:04:50 spla-repro volumio[21754]: info: Volumio called home Aug 28 21:04:50 spla-repro volumio[21754]: info: Spotify config file written Aug 28 21:04:50 spla-repro sudo[21966]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:50 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:50 spla-repro sudo[21966]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 21:04:50 spla-repro sudo[21966]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:50 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 28 21:04:50 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 28 21:04:50 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:50 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:50 spla-repro go-librespot[21968]: go-librespot daemon starting... Aug 28 21:04:50 spla-repro sudo[21966]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:50 spla-repro go-librespot[21969]: time="2026-08-28T21:04:50+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:50 spla-repro go-librespot[21969]: time="2026-08-28T21:04:50+02:00" level=debug msg="app state loaded" Aug 28 21:04:50 spla-repro go-librespot[21969]: time="2026-08-28T21:04:50+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:50 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:04:51 spla-repro volumio[21754]: info: No need to fix Spotify hosts Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+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 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+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 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:51 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=info msg="zeroconf server listening on port 39401" Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:51 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:51 spla-repro volumio[21754]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 28 21:04:51 spla-repro volumio[21754]: 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: 7 Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=debug msg="obtained new client token: AAGWrM34GVOZ86NUzr4Zcqlo51FhDbwl5Ctd1J27Odg+Cb9dixtyYNyUR0f+7DgS0Dxy545F+n/XP6U97DbgbeOMZP8K0pcsznHZn3xcofv42SkoVkAOBhp72QXRO4hkOBCgtQPimXny04FKVjn8UPoNrbywi0cVuz7fO8hBSEamWJJapJgbNyOdwTbRXHDNo9cHUaYutNYSPYNzKNRdYj65KszVo2AUQEld/4FbopeDQj/JAY5QCbcSwQ==" Aug 28 21:04:51 spla-repro volumio[21754]: info: Starting Shairport Sync Aug 28 21:04:51 spla-repro volumio[21754]: info: Starting Shairport Sync Aug 28 21:04:51 spla-repro volumio[21754]: info: Starting Shairport Sync Aug 28 21:04:51 spla-repro sudo[22021]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:51 spla-repro sudo[22025]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:04:51 spla-repro sudo[22025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:51 spla-repro sudo[22025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:51 spla-repro sudo[22023]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:51 spla-repro sudo[22021]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:04:51 spla-repro sudo[22021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:51 spla-repro sudo[22023]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:04:51 spla-repro sudo[22023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:51 spla-repro sudo[22021]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:51 spla-repro sudo[22027]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:51 spla-repro sudo[22030]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=debug msg="completed challenge" Aug 28 21:04:51 spla-repro volumio[21754]: 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: 7 Aug 28 21:04:51 spla-repro sudo[22023]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:51 spla-repro volumio[21754]: info: Received Get System Info Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 21:04:51 spla-repro sudo[22030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 21:04:51 spla-repro volumio[21754]: info: Discovery: Getting this device information Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:51 spla-repro sudo[22030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:51 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 21:04:51 spla-repro sudo[22027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:04:51 spla-repro sudo[22027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04:51+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:51 spla-repro volumio[21754]: 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 28 21:04:51 spla-repro volumio[21754]: info: Listing playlists Aug 28 21:04:51 spla-repro volumio[21754]: info: Listing playlists Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 21:04:51 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 21:04:51 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 21:04:51 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 21:04:51 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:51 spla-repro systemd[1]: shairport-sync.service: Consumed 1.897s CPU time. Aug 28 21:04:51 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:04:51 spla-repro go-librespot[21969]: time="2026-08-28T21:04: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 28 21:04:51 spla-repro sudo[22027]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:51 spla-repro sudo[22030]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:52 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:52 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:52 spla-repro sudo[22025]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:52 spla-repro sudo[22037]: volumio : unable to resolve host spla-repro: System error Aug 28 21:04:52 spla-repro volumio[21754]: info: Shairport-Sync Started Aug 28 21:04:52 spla-repro volumio[21754]: Error adding Membership: Error: addMembership EINVAL Aug 28 21:04:52 spla-repro volumio[21754]: info: Shairport-Sync Started Aug 28 21:04:52 spla-repro volumio[21754]: info: Shairport-Sync Started Aug 28 21:04:52 spla-repro sudo[22037]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 21:04:52 spla-repro sudo[22037]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:04:52 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:52 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:52 spla-repro sudo[22037]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:52 spla-repro volumio[21754]: info: Upmpdcli Daemon Started Aug 28 21:04:52 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:04:52.802+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 21:04:53 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:53] [connect] Successful connection Aug 28 21:04:53 spla-repro volumio-remote-updater[725]: [2026-08-28 21:04:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787943893 101 Aug 28 21:04:53 spla-repro volumio[21754]: 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: 9 Aug 28 21:04:53 spla-repro mpd[21950]: 2026-08-28T21:04:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 21:04:53 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 21:04:53 spla-repro sudo[21919]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:53 spla-repro sudo[21907]: pam_unix(sudo:session): session closed for user root Aug 28 21:04:53 spla-repro volumio[21754]: info: Completed starting Core Plugins Aug 28 21:04:53 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:53 spla-repro volumio[21754]: info: ----- MyVolumio plugins startup ---- Aug 28 21:04:53 spla-repro volumio[21754]: info: ------------------------------------------- Aug 28 21:04:53 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 21:04:54 spla-repro volumio[21754]: error: MPD error: The expression evaluated to a falsy value: Aug 28 21:04:54 spla-repro volumio[21754]: assert.ok(self.idling) Aug 28 21:04:54 spla-repro volumio[21754]: error: The expression evaluated to a falsy value: Aug 28 21:04:54 spla-repro volumio[21754]: assert.ok(self.idling) Aug 28 21:04:54 spla-repro volumio[21754]: error: updateQueue error: null Aug 28 21:04:54 spla-repro volumio[21754]: info: MPD running with PID21950 Aug 28 21:04:54 spla-repro volumio[21754]: ,establishing connection Aug 28 21:04:54 spla-repro volumio[21754]: error: updateQueue error: null Aug 28 21:04:54 spla-repro volumio[21754]: info: go-librespot daemon successfully initialized Aug 28 21:04:55 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 21:04:55 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:55 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:04:55 spla-repro go-librespot[22058]: go-librespot daemon starting... Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=debug msg="app state loaded" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+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 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+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 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=info msg="zeroconf server listening on port 41405" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=debug msg="obtained new client token: AAGJ/6xpqfNlUW3HgpY89gJTEBNB+hBMDm24QrA2/TifEwD0xfbk+JvL5dfPNzI2kz595t7AUTI5uO9Yz/H+WnWiOTWM1glT5c/dXM37X2fxaNL18ZaNeL3GOcMl3sE8XxKzEi2aZs61AWcThbjVTTJ9IdR/Oy4No2IyeWuZyHacgwYLBom3OT+Mj1e5S5UUwmzkwMh7QO0yq7+v6pNSy0lrVqXW9NX9jQft2gY2WBucRs3iIXGs/tTESw==" Aug 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+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 28 21:04:55 spla-repro go-librespot[22059]: time="2026-08-28T21:04:55+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 28 21:04:56 spla-repro go-librespot[22059]: time="2026-08-28T21:04:56+02:00" level=debug msg="completed keyexchange" Aug 28 21:04:56 spla-repro go-librespot[22059]: time="2026-08-28T21:04:56+02:00" level=debug msg="completed challenge" Aug 28 21:04:56 spla-repro go-librespot[22059]: time="2026-08-28T21:04:56+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:04:56 spla-repro go-librespot[22059]: time="2026-08-28T21:04:56+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:04:56 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:04:56 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:04:57 spla-repro volumio[21754]: info: Initializing connection to go-librespot Websocket Aug 28 21:04:57 spla-repro volumio[21754]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:04:58 spla-repro volumio[21754]: info: CoreCommandRouter::volumioGetState Aug 28 21:04:58 spla-repro volumio[21754]: info: CorePlayQueue::getTrack 0 Aug 28 21:04:59 spla-repro volumio[21754]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 21:04:59 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 21:04:59 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:00 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:00 spla-repro go-librespot[22068]: go-librespot daemon starting... Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="app state loaded" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+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 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+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 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+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 28 21:05:00 spla-repro volumio[21754]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="new websocket client" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=info msg="zeroconf server listening on port 40997" Aug 28 21:05:00 spla-repro volumio[21754]: info: Connection to go-librespot Websocket established Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="obtained new client token: AAF7sGluhFjeMtetYzc1lRbtChJ6wJbpVSVLjB3JOwIYgtcT5NBzoh+Ux67/e6aurrl37lj68jHfGQeP07rPUnU42a6HytX0Mw4aGoltQZgvrJjaNsc5TCDr1lBaY74RTDIZJbZ/d70w7nyx+NZNQPzaNSR2zVG4Hadk8GxofZYpS/W/kc7YGQTE+9UQJoLv6TMzLDolYuo/+GO157DNkHB3WMLko2yeTSwkMqtpmDRcSiXkXKdG20GwKQ==" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=debug msg="completed challenge" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:00 spla-repro go-librespot[22069]: time="2026-08-28T21:05:00+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:00 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:00 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:00 spla-repro volumio[21754]: info: Connection to go-librespot Websocket closed Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin bluetooth to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin multiroom to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin metavolumio to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin cd_controller to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 28 21:05:02 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 21:05:03 spla-repro volumio[21754]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 21:05:03 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 21:05:03 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:03 spla-repro volumio[21754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:03 spla-repro volumio[21754]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 21:05:03 spla-repro volumio[21754]: info: MyVolumio login type: Token Aug 28 21:05:03 spla-repro volumio[21754]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 21:05:03 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 28 21:05:03 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 21:05:03 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:04 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:04 spla-repro go-librespot[22092]: go-librespot daemon starting... Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="app state loaded" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+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 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+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 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+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 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=info msg="zeroconf server listening on port 46121" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="obtained new client token: AAFEbZkXO4hLuQGyTSDmThtfmEDz6nM/qeqYG0UF0/NNXZy4qnDXrBQMsawtOpvDjmcOOL6ZZrt2xNFXIHm9PuC1WO61pe6N0uHln2A8mwAo8n2aOgiXWdVhD18AhXf9K5NN9asBxM5p4MjlkoJcG+D37zfQ9VMACoZrzwALuJ2qt4FUaS3FJbVoaWW6kVg1mo0J+zRKNYu+dHnsUfAf9joKOtrb2nfLSu2XWYpziPOSEqwFvQfojOf6Aw==" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:04 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 28 21:05:04 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 28 21:05:04 spla-repro volumio[21754]: info: Streaming services startup Aug 28 21:05:04 spla-repro volumio[21754]: info: Starting Streaming Daemon Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="completed challenge" Aug 28 21:05:04 spla-repro sudo[22103]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:04 spla-repro volumio[21754]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 28 21:05:04 spla-repro sudo[22103]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 21:05:04 spla-repro sudo[22103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:04 spla-repro sudo[22103]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:04 spla-repro volumio[21754]: info: Getting Spotify volume Aug 28 21:05:04 spla-repro volumio[21754]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:04 spla-repro volumio[21754]: error: Cannot start Volumio Streaming Daemon Aug 28 21:05:04 spla-repro volumio[21754]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 21:05:04 spla-repro volumio[21754]: sudo: unable to resolve host spla-repro: System error Aug 28 21:05:04 spla-repro volumio[21754]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=debug msg="new websocket client" Aug 28 21:05:04 spla-repro volumio[21754]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Aug 28 21:05:04 spla-repro go-librespot[22093]: time="2026-08-28T21:05:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:04 spla-repro volumio[21754]: info: Connection to go-librespot Websocket established Aug 28 21:05:04 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:04 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:04 spla-repro volumio[21754]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:05:04 spla-repro volumio[21754]: Error: socket hang up Aug 28 21:05:04 spla-repro volumio[21754]: at connResetException (node:internal/errors:720:14) Aug 28 21:05:04 spla-repro volumio[21754]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 28 21:05:04 spla-repro volumio[21754]: at Socket.emit (node:events:526:35) Aug 28 21:05:04 spla-repro volumio[21754]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 28 21:05:04 spla-repro volumio[21754]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 28 21:05:04 spla-repro volumio[21754]: code: 'ECONNRESET', Aug 28 21:05:04 spla-repro volumio[21754]: response: undefined Aug 28 21:05:04 spla-repro volumio[21754]: } Aug 28 21:05:04 spla-repro volumio[21754]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:05:05 spla-repro sudo[22123]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:05 spla-repro sudo[22123]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 21:04' Aug 28 21:05:05 spla-repro sudo[22123]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:06 spla-repro sudo[22123]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:06 spla-repro volumio[21754]: sudo: unable to resolve host spla-repro: System error Aug 28 21:05:06 spla-repro volumio-remote-updater[725]: [2026-08-28 21:05:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 28 21:05:06 spla-repro volumio-remote-updater[725]: [2026-08-28 21:05:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 28 21:05:06 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:05:06.533+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 28 21:05:06 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:05:06.536+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:05:06 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:06 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 28 21:05:06 spla-repro systemd[1]: volumio.service: Consumed 34.144s CPU time. Aug 28 21:05:06 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:05:06 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:05:06 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10777. Aug 28 21:05:06 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 28 21:05:06 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 28 21:05:06 spla-repro systemd[1]: volumio.service: Consumed 34.144s CPU time. Aug 28 21:05:06 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 28 21:05:06 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 28 21:05:07 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:05:07.539+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:05:07 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 21:05:07 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:08 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:08 spla-repro go-librespot[22154]: go-librespot daemon starting... Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=debug msg="app state loaded" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+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 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+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 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+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 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=info msg="zeroconf server listening on port 35705" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:08 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:05:08.540+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=debug msg="obtained new client token: AAF0H/k53V+AJriITVdi4pF/s0NvInBhKIeo/ZWPlB740WFPoWHHC2bjKxUC7jGjuBpLdbnvFQ0/52TpD6oEDeO1GuV3ydi2vZSQ8iD97bH8pmVcP28IB+Bp3VnONDTSt54SLcVNeE8N1G5thzXbngFLNuWrcVdpLSu51l//vq4Y3sxuM7LX/82PY1tXszFEepGu51cXCB1uZRhwcEQ/wb6yD0gNA3v1VYhlTwa2LzBUYdMDUODnW8EeRw==" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=debug msg="completed challenge" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:08 spla-repro go-librespot[22155]: time="2026-08-28T21:05:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:08 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:08 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:09 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:09 spla-repro volumio[22139]: info: ----- Volumio3 ---- Aug 28 21:05:09 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:09 spla-repro volumio[22139]: info: ----- System startup ---- Aug 28 21:05:09 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:10 spla-repro volumio[22139]: info: MYVOLUMIO Environment detected Aug 28 21:05:10 spla-repro volumio[22139]: info: Plugin folders cleanup Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning into folder /volumio/app/plugins/ Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category audio_interface Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category miscellanea Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category music_service Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category plugins.json Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category system_controller Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category user_interface Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning into folder /data/plugins/ Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category audio_interface Aug 28 21:05:10 spla-repro volumio[22139]: info: Scanning category music_service Aug 28 21:05:10 spla-repro volumio[22139]: info: Plugin folders cleanup completed Aug 28 21:05:10 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:10 spla-repro volumio[22139]: info: ----- Core plugins startup ---- Aug 28 21:05:10 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:10 spla-repro volumio[22139]: info: Loading plugins from folder /volumio/app/plugins/ Aug 28 21:05:10 spla-repro volumio[22139]: info: Adding plugin upnp to MyMusic Plugins Aug 28 21:05:10 spla-repro volumio[22139]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 28 21:05:10 spla-repro volumio[22139]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 28 21:05:10 spla-repro volumio[22139]: info: Loading plugins from folder /data/plugins/ Aug 28 21:05:10 spla-repro volumio[22139]: info: Loading plugin "system"... Aug 28 21:05:10 spla-repro volumio[22139]: info: Loading plugin "appearance"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "network"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Refreshing Cached IP Addresses Aug 28 21:05:11 spla-repro volumio-remote-updater[725]: [2026-08-28 21:05:11] [connect] Successful connection Aug 28 21:05:11 spla-repro sudo[22178]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:11 spla-repro sudo[22180]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:11 spla-repro sudo[22178]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:05:11 spla-repro sudo[22180]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:05:11 spla-repro sudo[22180]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "services"... Aug 28 21:05:11 spla-repro sudo[22178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "volumio5onboarding"... Aug 28 21:05:11 spla-repro sudo[22180]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:11 spla-repro sudo[22178]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:11 spla-repro sudo[22187]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "alsa_controller"... Aug 28 21:05:11 spla-repro sudo[22187]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 28 21:05:11 spla-repro sudo[22187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:11 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "wizard"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "networkfs"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Starting Udev Watcher for removable devices Aug 28 21:05:11 spla-repro volumio[22139]: info: Ignoring mount for partition: boot Aug 28 21:05:11 spla-repro volumio[22139]: info: Ignoring mount for partition: volumio Aug 28 21:05:11 spla-repro volumio[22139]: info: Ignoring mount for partition: volumio_data Aug 28 21:05:11 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "volumio_command_line_client"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "upnp"... Aug 28 21:05:11 spla-repro volumio[22139]: info: [1787943911793] Starting Upmpd Daemon Aug 28 21:05:11 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "my_music"... Aug 28 21:05:11 spla-repro volumio[22139]: info: Loading plugin "mpd"... Aug 28 21:05:11 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 21:05:11 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:12 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:12 spla-repro go-librespot[22211]: go-librespot daemon starting... Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=debug msg="app state loaded" Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:12 spla-repro volumio[22139]: info: Loading plugin "upnp_browser"... Aug 28 21:05:12 spla-repro sudo[22187]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+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 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+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 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+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 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=info msg="zeroconf server listening on port 46523" Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=debug msg="obtained new client token: AAEnwGrkb/m5dO4de8BnBJ3rlxH5Km+gvXOrXJIm5R8qYWfCked8EU2kFac3UuVJtigvHY0x5OopmhV7Drgfdp9OMGg64pKFxTVK9tjyfEOxANBaSPmr8mvNXatS8vTRa1/YA6AoGmZc5BeS039diZRnXvuRfO0YLkRSQaktQgeAKJpX+UsTt09BQ/bn2NajsWGMK1y3pHC+pk6VKdy5YIDVwromYgI/GDyw8WqmvWbKvgN9H/UKwOpbdQ==" Aug 28 21:05:12 spla-repro go-librespot[22212]: time="2026-08-28T21:05:12+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:14 spla-repro volumio[22139]: info: Starting UPNP Browser Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "alarm-clock"... Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "airplay_emulation"... Aug 28 21:05:14 spla-repro volumio[22139]: info: Starting Shairport Sync Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "last_100"... Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "webradio"... Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "i2s_dacs"... Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "volumiodiscovery"... Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** For more information see Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:05:14 spla-repro volumio[22139]: *** WARNING *** For more information see Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** For more information see Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 28 21:05:14 spla-repro node[22139]: *** WARNING *** For more information see Aug 28 21:05:14 spla-repro volumio[22139]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 28 21:05:14 spla-repro volumio[22139]: info: Discovery: Started advertising with name: Spálňa-repro Aug 28 21:05:14 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 28 21:05:14 spla-repro volumio[22139]: info: Loading plugin "spop"... Aug 28 21:05:15 spla-repro volumio[22139]: info: Loading plugin "outputs"... Aug 28 21:05:15 spla-repro volumio[22139]: info: Loading plugin "albumart"... Aug 28 21:05:15 spla-repro volumio[22139]: info: Plugin example_plugin is not enabled Aug 28 21:05:15 spla-repro volumio[22139]: info: Loading plugin "inputs"... Aug 28 21:05:16 spla-repro volumio[22139]: info: Loading plugin "updater_comm"... Aug 28 21:05:16 spla-repro volumio[22139]: info: Plugin mpdemulation is not enabled Aug 28 21:05:16 spla-repro volumio[22139]: info: Loading plugin "rest_api"... Aug 28 21:05:16 spla-repro volumio[22139]: info: Loading plugin "websocket"... Aug 28 21:05:16 spla-repro volumio[22139]: info: Starting Socket.io Server version 1.7.4 Aug 28 21:05:16 spla-repro volumio[22139]: info: Plugin fusiondsp is not enabled Aug 28 21:05:16 spla-repro volumio[22139]: info: Loading i18n strings for locale sk Aug 28 21:05:16 spla-repro volumio[22139]: Updating browse sources language Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::initPlayerControls Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: Express server listening on port 3000 Aug 28 21:05:16 spla-repro volumio[22139]: [Metrics] WebUI: 7s 915.22ms Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::resetVolumioState Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::getcurrentVolume Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:05:16 spla-repro volumio[22139]: info: Cannot read play queue from file Aug 28 21:05:16 spla-repro volumio[22139]: info: Volumio Network Manager: Network status updated: 1 Aug 28 21:05:16 spla-repro volumio[22139]: 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 28 21:05:16 spla-repro volumio[22139]: Unable to parse: Aug 28 21:05:16 spla-repro volumio[22139]: Simple mixer control 'Master',0 Aug 28 21:05:16 spla-repro volumio[22139]: Capabilities: volume volume-joined Aug 28 21:05:16 spla-repro volumio[22139]: Playback channels: Mono Aug 28 21:05:16 spla-repro volumio[22139]: Capture channels: Mono Aug 28 21:05:16 spla-repro volumio[22139]: Limits: 0 - 248 Aug 28 21:05:16 spla-repro volumio[22139]: Mono: 112 [45%] Aug 28 21:05:16 spla-repro volumio[22139]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:05:16 spla-repro volumio[22224]: Forking 3 albumart workers Aug 28 21:05:16 spla-repro volumio[22139]: 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 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:16 spla-repro volumio[22139]: 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 28 21:05:16 spla-repro volumio[22139]: info: Received Get System Info Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 28 21:05:16 spla-repro volumio[22139]: info: Discovery: Getting this device information Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:16 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 28 21:05:16 spla-repro volumio[22139]: 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 28 21:05:16 spla-repro volumio[22139]: Unable to parse: Aug 28 21:05:16 spla-repro volumio[22139]: Simple mixer control 'Master',0 Aug 28 21:05:16 spla-repro volumio[22139]: Capabilities: volume volume-joined Aug 28 21:05:16 spla-repro volumio[22139]: Playback channels: Mono Aug 28 21:05:16 spla-repro volumio[22139]: Capture channels: Mono Aug 28 21:05:16 spla-repro volumio[22139]: Limits: 0 - 248 Aug 28 21:05:16 spla-repro volumio[22139]: Mono: 112 [45%] Aug 28 21:05:16 spla-repro volumio[22139]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::pushState Aug 28 21:05:16 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioPushState Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::updateTrackBlock Aug 28 21:05:16 spla-repro volumio[22139]: info: CorePlayQueue::getTrackBlock Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioRetrievevolume Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::setRepeat null single undefined Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::pushState Aug 28 21:05:16 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioPushState Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::setRandom null Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreStateMachine::pushState Aug 28 21:05:16 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::volumioPushState Aug 28 21:05:16 spla-repro volumio[22139]: info: Setting Device type: Raspberry PI Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 28 21:05:16 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 28 21:05:17 spla-repro volumio[22139]: info: Completed loading Core Plugins Aug 28 21:05:17 spla-repro volumio[22139]: info: Preparing to generate the ALSA configuration file Aug 28 21:05:17 spla-repro volumio[22139]: 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 28 21:05:17 spla-repro volumio[22139]: Unable to parse: Aug 28 21:05:17 spla-repro volumio[22139]: Simple mixer control 'Master',0 Aug 28 21:05:17 spla-repro volumio[22139]: Capabilities: volume volume-joined Aug 28 21:05:17 spla-repro volumio[22139]: Playback channels: Mono Aug 28 21:05:17 spla-repro volumio[22139]: Capture channels: Mono Aug 28 21:05:17 spla-repro volumio[22139]: Limits: 0 - 248 Aug 28 21:05:17 spla-repro volumio[22139]: Mono: 112 [45%] Aug 28 21:05:17 spla-repro volumio[22139]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: Found device kuchyna-repro Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 28 21:05:17 spla-repro volumio[22139]: 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: 5 Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: Found device kupelna-repro Aug 28 21:05:17 spla-repro volumio[22139]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 28 21:05:17 spla-repro volumio[22139]: Unable to parse: Aug 28 21:05:17 spla-repro volumio[22139]: Simple mixer control 'Master',0 Aug 28 21:05:17 spla-repro volumio[22139]: Capabilities: volume volume-joined Aug 28 21:05:17 spla-repro volumio[22139]: Playback channels: Mono Aug 28 21:05:17 spla-repro volumio[22139]: Capture channels: Mono Aug 28 21:05:17 spla-repro volumio[22139]: Limits: 0 - 248 Aug 28 21:05:17 spla-repro volumio[22139]: Mono: 112 [45%] Aug 28 21:05:17 spla-repro volumio[22139]: info: VolumeController:: Volume=undefined Mute =false Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreStateMachine::pushState Aug 28 21:05:17 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::volumioPushState Aug 28 21:05:17 spla-repro volumio[22139]: info: Asound.conf file unchanged, so no further update is needed Aug 28 21:05:17 spla-repro volumio[22139]: info: Output device has changed, restarting MPD Aug 28 21:05:17 spla-repro volumio[22139]: info: Output device has changed, restarting Shairport Sync Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:17 spla-repro sudo[22280]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:17 spla-repro volumio[22139]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:05:17 spla-repro sudo[22280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:05:17 spla-repro sudo[22280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:17 spla-repro sudo[22282]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:17 spla-repro sudo[22280]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:17 spla-repro volumio[22139]: info: ___________ START PLUGINS ___________ Aug 28 21:05:17 spla-repro sudo[22282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:05:17 spla-repro volumio[22139]: info: ControllerMpd::onStart: Initializing MPD Aug 28 21:05:17 spla-repro volumio[22139]: info: Creating MPD Configuration file Aug 28 21:05:17 spla-repro sudo[22282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:05:17 spla-repro volumio[22139]: info: [1787943917574] CoreMusicLibrary::Adding element Mediálne servery Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:05:17 spla-repro sudo[22289]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:17 spla-repro sudo[22293]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:17 spla-repro volumio[22139]: info: UPNP Browser: Client initialized successfully Aug 28 21:05:17 spla-repro sudo[22289]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 28 21:05:17 spla-repro sudo[22293]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 28 21:05:17 spla-repro sudo[22289]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:17 spla-repro sudo[22293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:17 spla-repro sudo[22293]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:17 spla-repro sudo[22294]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:17 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:17 spla-repro sudo[22294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 28 21:05:17 spla-repro sudo[22294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:17 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:05:17 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:05:17 spla-repro systemd[1]: mpd.service: Consumed 5.907s CPU time. Aug 28 21:05:17 spla-repro volumio[22139]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:17 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:05:17 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:05:17 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:05:17 spla-repro volumio5-onboarding[30095]: time=2026-08-28T21:05:17.840+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 28 21:05:17 spla-repro volumio[22139]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 28 21:05:17 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:05:17 spla-repro volumio[22139]: info: [1787943917876] CoreMusicLibrary::Adding element Last_100 Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 28 21:05:17 spla-repro volumio[22139]: info: [1787943917882] CoreMusicLibrary::Adding element Webradio Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 28 21:05:17 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:05:17 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:05:17 spla-repro sudo[22289]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:17 spla-repro volumio[22139]: info: Initializing BBC Radios Aug 28 21:05:17 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 28 21:05:17 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 28 21:05:17 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 28 21:05:17 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 28 21:05:17 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 28 21:05:17 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 28 21:05:18 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 28 21:05:18 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:05:18 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:18 spla-repro volumio[22139]: info: Creating Spotify config file Aug 28 21:05:18 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:18 spla-repro sudo[22314]: root : unable to resolve host spla-repro: System error Aug 28 21:05:18 spla-repro sudo[22314]: sudo: unable to resolve host spla-repro: System error Aug 28 21:05:18 spla-repro sudo[22314]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 28 21:05:18 spla-repro sudo[22314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 28 21:05:18 spla-repro sudo[22314]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:18 spla-repro volumio[22139]: info: Volumio Calling Home Aug 28 21:05:19 spla-repro volumio[22241]: Starting albumart workers Aug 28 21:05:19 spla-repro volumio[22240]: Starting albumart workers Aug 28 21:05:19 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:05:19 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:19 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:19 spla-repro volumio[22139]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:05:19 spla-repro volumio[22139]: info: Discovery: Found device Spálňa-repro Aug 28 21:05:19 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:19 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:19 spla-repro volumio[22139]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 28 21:05:19 spla-repro volumio[22139]: info: Discovery: Found device Spálňa-repro Aug 28 21:05:19 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:19 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:19 spla-repro volumio[22139]: info: Discovery: Connected to remote: 192.168.200.201 Aug 28 21:05:20 spla-repro volumio[22139]: info: MPD Permissions set Aug 28 21:05:20 spla-repro volumio[22139]: info: MPD Permissions set Aug 28 21:05:20 spla-repro volumio[22242]: Starting albumart workers Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:20 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:20 spla-repro volumio[22139]: info: Discovery: Connected to remote: 192.168.200.202 Aug 28 21:05:20 spla-repro volumio[22139]: info: Volumio called home Aug 28 21:05:20 spla-repro volumio[22139]: info: Spotify config file written Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:20 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:20 spla-repro sudo[22330]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:20 spla-repro sudo[22330]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 28 21:05:20 spla-repro sudo[22330]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:20 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 28 21:05:20 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 28 21:05:20 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:20 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:20 spla-repro go-librespot[22332]: go-librespot daemon starting... Aug 28 21:05:20 spla-repro sudo[22330]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:20 spla-repro go-librespot[22333]: time="2026-08-28T21:05:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:20 spla-repro go-librespot[22333]: time="2026-08-28T21:05:20+02:00" level=debug msg="app state loaded" Aug 28 21:05:20 spla-repro volumio[22139]: 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 28 21:05:20 spla-repro go-librespot[22333]: time="2026-08-28T21:05:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:20 spla-repro volumio[22139]: info: No need to fix Spotify hosts Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+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 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+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 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+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 28 21:05:21 spla-repro volumio[22139]: info: Listing playlists Aug 28 21:05:21 spla-repro volumio[22139]: info: Listing playlists Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=info msg="zeroconf server listening on port 33187" Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:21 spla-repro volumio[22139]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 28 21:05:21 spla-repro volumio[22139]: info: Starting Shairport Sync Aug 28 21:05:21 spla-repro volumio[22139]: info: Starting Shairport Sync Aug 28 21:05:21 spla-repro sudo[22365]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:21 spla-repro volumio[22139]: info: Starting Shairport Sync Aug 28 21:05:21 spla-repro sudo[22365]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:05:21 spla-repro sudo[22365]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=debug msg="obtained new client token: AAEuFzEXoK2UQkdunptoZFi+BSE0fup+yP9n/UMCvgLm/1XExU/8lMWybAZBDrqfKAZIYxYhrxNTp9W97wnNIaXcbeiConiHTzH3Jel0ryAsuadrGphyZcrr+FjJeUYKNjevtEgHamDh20g8IzLAeBD25R43jZTxnN3VZKCh/ugabet0/gI26z/vXiSM9Ib+xGlYvd2UHVerzvkx+50LcovDOqSDXUUuqBHzYyjV45jyxYwva03+846DnA==" Aug 28 21:05:21 spla-repro sudo[22367]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:21 spla-repro sudo[22367]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:05:21 spla-repro sudo[22367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:21 spla-repro sudo[22369]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:21 spla-repro sudo[22369]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 28 21:05:21 spla-repro sudo[22369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:21 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 21:05:21 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 21:05:21 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:05:21 spla-repro systemd[1]: shairport-sync.service: Consumed 1.957s CPU time. Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:21 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:21 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=debug msg="completed challenge" Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:21 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:05:21 spla-repro sudo[22385]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:21 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 28 21:05:21 spla-repro sudo[22385]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 28 21:05:21 spla-repro sudo[22367]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:21 spla-repro sudo[22385]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:21 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 28 21:05:21 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:05:21 spla-repro volumio[22139]: info: Shairport-Sync Started Aug 28 21:05:21 spla-repro sudo[22385]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:21 spla-repro volumio[22139]: Error adding Membership: Error: addMembership EINVAL Aug 28 21:05:21 spla-repro sudo[22392]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:21 spla-repro go-librespot[22333]: time="2026-08-28T21:05:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:22 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 28 21:05:22 spla-repro sudo[22392]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 28 21:05:22 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:22 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:22 spla-repro sudo[22392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:22 spla-repro sudo[22365]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:22 spla-repro sudo[22392]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:22 spla-repro volumio[22139]: info: Shairport-Sync Started Aug 28 21:05:22 spla-repro sudo[22369]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:22 spla-repro sudo[22397]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:22 spla-repro volumio[22139]: info: Shairport-Sync Started Aug 28 21:05:22 spla-repro sudo[22397]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 28 21:05:22 spla-repro sudo[22397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:22 spla-repro sudo[22397]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:22 spla-repro volumio[22139]: info: Upmpdcli Daemon Started Aug 28 21:05:24 spla-repro volumio-remote-updater[725]: [2026-08-28 21:05:24] [connect] Successful connection Aug 28 21:05:24 spla-repro volumio-remote-updater[725]: [2026-08-28 21:05:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787943924 101 Aug 28 21:05:24 spla-repro volumio[22139]: 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 28 21:05:24 spla-repro mpd[22324]: 2026-08-28T21:05:24 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 28 21:05:24 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 28 21:05:24 spla-repro sudo[22282]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:24 spla-repro sudo[22294]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:24 spla-repro volumio[22139]: info: Completed starting Core Plugins Aug 28 21:05:24 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:24 spla-repro volumio[22139]: info: ----- MyVolumio plugins startup ---- Aug 28 21:05:24 spla-repro volumio[22139]: info: ------------------------------------------- Aug 28 21:05:24 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 28 21:05:24 spla-repro volumio[22139]: error: MPD error: The expression evaluated to a falsy value: Aug 28 21:05:24 spla-repro volumio[22139]: assert.ok(self.idling) Aug 28 21:05:24 spla-repro volumio[22139]: error: The expression evaluated to a falsy value: Aug 28 21:05:24 spla-repro volumio[22139]: assert.ok(self.idling) Aug 28 21:05:24 spla-repro volumio[22139]: info: go-librespot daemon successfully initialized Aug 28 21:05:24 spla-repro volumio[22139]: error: updateQueue error: null Aug 28 21:05:24 spla-repro volumio[22139]: info: MPD running with PID22324 Aug 28 21:05:24 spla-repro volumio[22139]: ,establishing connection Aug 28 21:05:24 spla-repro volumio[22139]: error: updateQueue error: null Aug 28 21:05:25 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 28 21:05:25 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:25 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:25 spla-repro go-librespot[22424]: go-librespot daemon starting... Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=debug msg="app state loaded" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+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 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+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 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+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 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=info msg="zeroconf server listening on port 40307" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=debug msg="obtained new client token: AAH/46f2LK/X6/dQGShqalJuRtdeF6DT5rZ0o+CxVcbwkZdhzd0/28dTbquIjsO8GNLDPD1Lwp/1uO4qTfmYq3Qgym7SJ/KhOUcWBhii6yb1UroSGwT828DmjbblTV1eT4xZdNmZgdy+M8KiKI4w6f6D2B9VHZyyDEcxstWmmUKafAdPYJuHHd8dEWyLqwWjEUeorKvRxIhpcuia8YLy7ZOWU3E6pBsQWumHbfrmX+wRcbNuqxs5aIKnsQ==" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=debug msg="completed challenge" Aug 28 21:05:25 spla-repro go-librespot[22425]: time="2026-08-28T21:05:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:26 spla-repro go-librespot[22425]: time="2026-08-28T21:05: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 28 21:05:26 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:26 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:27 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:27 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:28 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:28 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:29 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 28 21:05:29 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:29 spla-repro volumio[22139]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 28 21:05:29 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:29 spla-repro go-librespot[22434]: go-librespot daemon starting... Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=debug msg="app state loaded" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+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 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+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 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=info msg="zeroconf server listening on port 38619" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=debug msg="obtained new client token: AAEQxzs7GkZuQkPMnA1tm5btfqHWmZyH6AsV7Lm4xNFf9cnlcM3DyPHHZf0yOnqaZT52UAl+sH8K1oG0jsP9q/ttcgZTFMsnVGJKPKwjezkWscVIVv0GfWa51Isbr6pqW1OOhFrqSjqKqyXhvc2TpjNgZR79N9b6fgiJ2VutyjTrFwqrhrClgosfkk/c6ZpIBV77OFh8Vt/BFtO0wXoG7PUriM9H2pYCG1f+cXZab6EnGKEeUe6weE0wXA==" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=debug msg="completed challenge" Aug 28 21:05:29 spla-repro go-librespot[22435]: time="2026-08-28T21:05:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:30 spla-repro go-librespot[22435]: time="2026-08-28T21:05:30+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:30 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:30 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:30 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:30 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin bluetooth to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin multiroom to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin metavolumio to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin cd_controller to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 28 21:05:32 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 28 21:05:33 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 28 21:05:33 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:33 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:33 spla-repro go-librespot[22459]: go-librespot daemon starting... Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=debug msg="app state loaded" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+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 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+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 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=info msg="zeroconf server listening on port 34651" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=debug msg="obtained new client token: AAHLSL3LC9qvfmcl3g+ZoFCd94kRvmfYd+VmwYBz5oXcjhHMfdf6hSyCRjhWMzOctxKIujCa2g/4O6xexMx1MndVTE7bIPDB8T2fNMXtxqoURC2B+2TvP8iOymbkAH+o/jCh9ZAXFQuenGvLFVbSdh/5NLA+uPGHaVoqGskJlFgLe+nf3TzzK6kHpTBiQQ1iKVxGP5DbZUkLxT6boSbpuK7p/3textFqrafCI9ZyhuRlSg/XxzLUgD0Dyw==" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:33 spla-repro go-librespot[22460]: time="2026-08-28T21:05:33+02:00" level=debug msg="completed challenge" Aug 28 21:05:34 spla-repro volumio[22139]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 28 21:05:34 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 28 21:05:34 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:34 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:34 spla-repro volumio[22139]: info: Starting MyVolumio Remote Streaming Endpoints Aug 28 21:05:34 spla-repro go-librespot[22460]: time="2026-08-28T21:05:34+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:34 spla-repro volumio[22139]: info: MyVolumio login type: Token Aug 28 21:05:34 spla-repro volumio[22139]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 28 21:05:34 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 28 21:05:34 spla-repro go-librespot[22460]: time="2026-08-28T21:05:34+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:34 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:34 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:35 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 28 21:05:35 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 28 21:05:35 spla-repro volumio[22139]: info: Streaming services startup Aug 28 21:05:35 spla-repro volumio[22139]: info: Starting Streaming Daemon Aug 28 21:05:35 spla-repro sudo[22470]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:35 spla-repro volumio[22139]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 28 21:05:35 spla-repro sudo[22470]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 21:05:35 spla-repro sudo[22470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:35 spla-repro sudo[22470]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:35 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:35 spla-repro volumio[22139]: error: Cannot start Volumio Streaming Daemon Aug 28 21:05:35 spla-repro volumio[22139]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 21:05:35 spla-repro volumio[22139]: sudo: unable to resolve host spla-repro: System error Aug 28 21:05:35 spla-repro volumio[22139]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 21:05:35 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:35 spla-repro volumio[22139]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 28 21:05:36 spla-repro volumio[22139]: info: MyVolumio token set successfully Aug 28 21:05:36 spla-repro volumio[22139]: info: MYVOLUMIO: Adding device Aug 28 21:05:36 spla-repro volumio[22139]: info: MYVOLUMIO: Evaluating Server Aug 28 21:05:36 spla-repro volumio[22139]: info: MyVolumio status changed Aug 28 21:05:36 spla-repro volumio[22139]: info: Streaming services startup Aug 28 21:05:36 spla-repro volumio[22139]: info: Starting Streaming Daemon Aug 28 21:05:36 spla-repro volumio[22139]: info: Removing browser output: myVolumio user plan is not superstar Aug 28 21:05:36 spla-repro volumio[22139]: info: Removing audio output: Aug 28 21:05:36 spla-repro volumio[22139]: info: Stoppping Tunnel 1 Aug 28 21:05:36 spla-repro sudo[22497]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:36 spla-repro sudo[22497]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 28 21:05:36 spla-repro sudo[22497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:36 spla-repro sudo[22500]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:36 spla-repro sudo[22500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 28 21:05:36 spla-repro sudo[22500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:36 spla-repro sudo[22497]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:36 spla-repro volumio[22139]: error: Cannot start Volumio Streaming Daemon Aug 28 21:05:36 spla-repro volumio[22139]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 28 21:05:36 spla-repro volumio[22139]: sudo: unable to resolve host spla-repro: System error Aug 28 21:05:36 spla-repro volumio[22139]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05: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 28 21:05:36 spla-repro sudo[22500]: pam_unix(sudo:session): session closed for user root Aug 28 21:05:36 spla-repro volumio[22139]: info: Remote SSH Stopped Aug 28 21:05:37 spla-repro volumio[22139]: info: Setting Geolocation for MyVolumio to eu6 Aug 28 21:05:37 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:37 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:37 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:37 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 28 21:05:37 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:37 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:37 spla-repro go-librespot[22504]: go-librespot daemon starting... Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=debug msg="app state loaded" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:37 spla-repro volumio[22139]: info: Successfully Added MyVolumio device Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+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 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+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 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=info msg="zeroconf server listening on port 34289" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=debug msg="obtained new client token: AAEJBXlAA9dmXM82+NPjO6o1Wo8a9WgNT05JBDOiudqRuG+vY1sBov17i3gEAkYYsZOV8FCxIj/khHXFV6dKSFVaM26oqhmWm1LiU7g7QLGNxEyFrJUYraTwf6EM963soZ1ORtBqSPMxj0dLv4iGnupiJOXmmDtzneX1vKuELWrzG+esPDJSuxQNSSikW+cju/z9T6il0z1bj4erkp2oxeNtwe6pMzeBH0cdGbGP84wZf9nB4fa4bcEz9A==" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=debug msg="completed challenge" Aug 28 21:05:37 spla-repro go-librespot[22505]: time="2026-08-28T21:05:37+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:38 spla-repro volumio[22139]: info: Updating MyVolumio device info Aug 28 21:05:38 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:38 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:38 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:38 spla-repro go-librespot[22505]: time="2026-08-28T21:05: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 28 21:05:38 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:38 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:38 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:38 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:38 spla-repro volumio[22139]: info: Listing playlists Aug 28 21:05:38 spla-repro volumio[22139]: info: Listing playlists Aug 28 21:05:38 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:38 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:38 spla-repro volumio[22139]: info: Successfully Updated MyVolumio device Aug 28 21:05:41 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 28 21:05:41 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:41 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:41 spla-repro go-librespot[22514]: go-librespot daemon starting... Aug 28 21:05:41 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:41 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=debug msg="app state loaded" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05: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 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05: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 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05: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 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=info msg="zeroconf server listening on port 43365" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=debug msg="obtained new client token: AAFJN4SX6s5vabjTDcnm/Y+fDbrKSF4UKDrYowxQ0x2rVkdNlAF3kA1QAN2yfim8wiYNS8w40YQJuSmBCvX9L0704JlcjfEAzAUll7sbbi214jDKzFdxr9POxvGBAEZbiyIg8xkeKD96EN71ZH7Wk4APgyT/IJJ3bUHAna//L0iPxity3KvS001HE+f8uM/b4ErRQZRS3z15QHavgmf+OJB34/T5Bcndt35L+lScNyfPl+R5pN7v+v9Cxg==" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+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 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=debug msg="completed challenge" Aug 28 21:05:41 spla-repro go-librespot[22515]: time="2026-08-28T21:05:41+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:42 spla-repro go-librespot[22515]: time="2026-08-28T21:05: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 28 21:05:42 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:42 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:44 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:44 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:45 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 28 21:05:45 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:45 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:45 spla-repro go-librespot[22538]: go-librespot daemon starting... Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=debug msg="app state loaded" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+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 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+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 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+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 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=info msg="zeroconf server listening on port 33709" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=debug msg="obtained new client token: AAH9vBKS9T8OKSsiGCcLO4btpNqmJ67lCMFx5f2xuOGm4Zp2sXAhxFG7ounAbORIXz85RTzPIeAbcvGGQ+2mxwN2gg20lBqyDfCb4hOoXWY+OceK+YFyaEPZIOIaHQQ+ywzbL0CNa3hDeKbQ0O1V45AQShcDh3Io6+G5oMNPyQVCoME9fP7QLv0M9vBX1Do4d009Zxx43CJ/k3VxaoUqOd+5BlBIJDLstl/foWBnZ7RiZ529uMo5SfMgYg==" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=debug msg="completed challenge" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:45 spla-repro go-librespot[22539]: time="2026-08-28T21:05:45+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:45 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:45 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:47 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:47 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:48 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:48 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:48 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:05:48 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:48 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 28 21:05:49 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 28 21:05:49 spla-repro volumio[22139]: 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 28 21:05:49 spla-repro volumio-remote-updater[725]: Test mode disabled Aug 28 21:05:49 spla-repro volumio-remote-updater[725]: Alpha mode disabled Aug 28 21:05:49 spla-repro volumio-remote-updater[725]: Alpha legacy test mode disabled Aug 28 21:05:49 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 28 21:05:49 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetState Aug 28 21:05:49 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:49 spla-repro volumio[22139]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 28 21:05:49 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 28 21:05:49 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 28 21:05:49 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:49 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:49 spla-repro go-librespot[22552]: go-librespot daemon starting... Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=debug msg="app state loaded" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+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 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+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 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+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 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=info msg="zeroconf server listening on port 35031" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=debug msg="obtained new client token: AAHmMP7q0go7Zs0zWiPUnAF77J1dPqZQhruRCuZjNS5VAOR+gHMts4btXpPMsceuvyKj9EHX6ZLCZf8E3msrmadoMv/DZQmu1TxM6UozD3Jm7ppNuNPJYFBcjYcTxi+Xd/CYQr9URX6ERBWXN1D3qRXt1QEEfRSVTHL/JLGhhcvR7Lrnc/8pxlu2nG++ejC19t4O7eKWwygra7uaMyLYurOU7pNp9ZOd5m6PJgxY+s+mTq1rpkIkw+ocjw==" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=debug msg="completed challenge" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:49 spla-repro go-librespot[22553]: time="2026-08-28T21:05:49+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:49 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:49 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:50 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:50 spla-repro volumio[22139]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:52 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 28 21:05:52 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:53 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:53 spla-repro go-librespot[22578]: go-librespot daemon starting... Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="app state loaded" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+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 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+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 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+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 28 21:05:53 spla-repro volumio[22139]: info: Initializing connection to go-librespot Websocket Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="new websocket client" Aug 28 21:05:53 spla-repro volumio[22139]: info: Connection to go-librespot Websocket established Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=info msg="zeroconf server listening on port 37969" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="obtained new client token: AAEOFnhRw4gwiW6hst7J8rshcRGhTrPXDj8hwwZXhWHqBwpBqMIIzN8mIYw4vbXqjTm3mBtpZN0nbaGfFjykv5VXiO/fZAu7unUCqBQUYIhCSj3SxFnmFgmC63BwuxdBegYVBeZYT8nPAgkNyKunZA2ty8fwV+ugiw1z3+GViMSUkLUIqiNL5tJVnpUSM5Tl4xm7luat59E/3cZG9k5Erz8St3dLZV84eFwyhtq2usI69eNfyFjQEQgPIA==" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=debug msg="completed challenge" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 28 21:05:53 spla-repro go-librespot[22579]: time="2026-08-28T21:05:53+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 28 21:05:53 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 28 21:05:53 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 28 21:05:53 spla-repro volumio[22139]: info: Connection to go-librespot Websocket closed Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::volumioGetBrowseSources Aug 28 21:05:54 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 28 21:05:55 spla-repro volumio[22139]: error: MyVolumio Plugin failed to authenticate in a timely fashion Aug 28 21:05:55 spla-repro volumio[22139]: info: Completed starting MyVolumio Plugin Aug 28 21:05:55 spla-repro volumio[22139]: [Metrics] CommandRouter: 46s 35.36ms Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::volumiosetStartupVolume Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 28 21:05:55 spla-repro volumio[22139]: info: VolumeController:: Setting startup Volume 45 Aug 28 21:05:55 spla-repro volumio[22139]: info: VolumeController::SetAlsaVolume45 Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::Close All Modals sent Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::Close All Modals sent Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreStateMachine::pushState Aug 28 21:05:55 spla-repro volumio[22139]: info: CorePlayQueue::getTrack 0 Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 28 21:05:55 spla-repro volumio[22139]: info: CoreCommandRouter::volumioPushState Aug 28 21:05:56 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 28 21:05:56 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 28 21:05:56 spla-repro volumio[22139]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 28 21:05:56 spla-repro volumio[22139]: info: Getting Spotify volume Aug 28 21:05:56 spla-repro volumio[22139]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:05:56 spla-repro volumio[22139]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 28 21:05:56 spla-repro volumio[22139]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 28 21:05:56 spla-repro volumio[22139]: errno: -111, Aug 28 21:05:56 spla-repro volumio[22139]: code: 'ECONNREFUSED', Aug 28 21:05:56 spla-repro volumio[22139]: syscall: 'connect', Aug 28 21:05:56 spla-repro volumio[22139]: address: '127.0.0.1', Aug 28 21:05:56 spla-repro volumio[22139]: port: 9879, Aug 28 21:05:56 spla-repro volumio[22139]: response: undefined Aug 28 21:05:56 spla-repro volumio[22139]: } Aug 28 21:05:56 spla-repro volumio[22139]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 21:05:56 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 28 21:05:56 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:56 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 28 21:05:56 spla-repro go-librespot[22601]: go-librespot daemon starting... Aug 28 21:05:56 spla-repro go-librespot[22602]: time="2026-08-28T21:05:56+02:00" level=info msg="running go-librespot 0.7.1" Aug 28 21:05:56 spla-repro go-librespot[22602]: time="2026-08-28T21:05:56+02:00" level=debug msg="app state loaded" Aug 28 21:05:56 spla-repro go-librespot[22602]: time="2026-08-28T21:05:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+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 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+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 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+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 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=info msg="zeroconf server listening on port 35133" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 28 21:05:57 spla-repro sudo[22613]: volumio : unable to resolve host spla-repro: System error Aug 28 21:05:57 spla-repro sudo[22613]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-28 21:04' Aug 28 21:05:57 spla-repro sudo[22613]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=debug msg="obtained new client token: AAFtvp7EHs+QG6qDbKB6AQ6q8b/SJmQa4fgkbhwwv6i/msd4AvJY5RAVk3oLlq8fjB21uex/raIshfiE1U1QxWPR1eDS+HHvoygY8vpJ0/xvj5LDPRi0+vluN46Avxgi6SlxNJcc3Ip1rjeTn7ArhyDc9Lx9QvZsPgtc1Vx4yDAFdfOKs9rP9lAblZTe0bSNc8A3iw+hI58goEPkqoKOhEMW6a4up853+D6lccrPck6ksuMCdvWNd8o=" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=debug msg="completed keyexchange" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=debug msg="completed challenge" Aug 28 21:05:57 spla-repro go-librespot[22602]: time="2026-08-28T21:05:57+02:00" level=info msg="authenticated AP" username="4b*********************lb" 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"