Aug 25 22:40:00 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 22:40:00 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:00 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:00 spla-repro go-librespot[32168]: go-librespot daemon starting... Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=debug msg="app state loaded" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40: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 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40: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 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40: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 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=info msg="zeroconf server listening on port 42423" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=debug msg="obtained new client token: AAEeK79SYoOC6LuLUE0Uf6JGbz6t6pJAcdK29Nh7NwJjYDWe0PJGUssqEJLE/CdK5Vb6mN0WQK0/+MQ2brIYdogQyRASg9IBkK9wfWUhMHkEI7ItJcuODeNlAq3bO8dVIxC7m8YAIqxSoinuiHqmQU4xPSZQSaUbPsEWeg2h5Xhb7Q+yhCfhCBYT8gCb/1mGh7lHlhs2xhFSHnpfeaZki9xSUi5Meg2KKihn+emyAEToqe/qAyPZlIjkVg==" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=debug msg="completed challenge" Aug 25 22:40:00 spla-repro go-librespot[32169]: time="2026-08-25T22:40:00+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "outputs"... Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "albumart"... Aug 25 22:40:01 spla-repro go-librespot[32169]: time="2026-08-25T22:40:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:01 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:01 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:01 spla-repro volumio[32100]: info: Plugin example_plugin is not enabled Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "inputs"... Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "updater_comm"... Aug 25 22:40:01 spla-repro volumio[32100]: info: Plugin mpdemulation is not enabled Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "rest_api"... Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading plugin "websocket"... Aug 25 22:40:01 spla-repro volumio[32100]: info: Starting Socket.io Server version 1.7.4 Aug 25 22:40:01 spla-repro volumio[32100]: info: Plugin fusiondsp is not enabled Aug 25 22:40:01 spla-repro volumio[32100]: info: Loading i18n strings for locale sk Aug 25 22:40:01 spla-repro volumio[32100]: Updating browse sources language Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::initPlayerControls Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: Express server listening on port 3000 Aug 25 22:40:01 spla-repro volumio[32100]: [Metrics] WebUI: 6s 663.26ms Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::resetVolumioState Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::getcurrentVolume Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:40:01 spla-repro volumio[32100]: info: Cannot read play queue from file Aug 25 22:40:01 spla-repro volumio[32100]: info: Volumio Network Manager: Network status updated: 1 Aug 25 22:40:01 spla-repro volumio[32100]: 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 25 22:40:01 spla-repro volumio[32178]: Forking 3 albumart workers Aug 25 22:40:01 spla-repro volumio[32100]: Unable to parse: Aug 25 22:40:01 spla-repro volumio[32100]: Simple mixer control 'Master',0 Aug 25 22:40:01 spla-repro volumio[32100]: Capabilities: volume volume-joined Aug 25 22:40:01 spla-repro volumio[32100]: Playback channels: Mono Aug 25 22:40:01 spla-repro volumio[32100]: Capture channels: Mono Aug 25 22:40:01 spla-repro volumio[32100]: Limits: 0 - 248 Aug 25 22:40:01 spla-repro volumio[32100]: Mono: 112 [45%] Aug 25 22:40:01 spla-repro volumio[32100]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:01 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:01 spla-repro volumio[32100]: 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 25 22:40:01 spla-repro volumio[32100]: Unable to parse: Aug 25 22:40:01 spla-repro volumio[32100]: Simple mixer control 'Master',0 Aug 25 22:40:01 spla-repro volumio[32100]: Capabilities: volume volume-joined Aug 25 22:40:01 spla-repro volumio[32100]: Playback channels: Mono Aug 25 22:40:01 spla-repro volumio[32100]: Capture channels: Mono Aug 25 22:40:01 spla-repro volumio[32100]: Limits: 0 - 248 Aug 25 22:40:01 spla-repro volumio[32100]: Mono: 112 [45%] Aug 25 22:40:01 spla-repro volumio[32100]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::pushState Aug 25 22:40:01 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::updateTrackBlock Aug 25 22:40:01 spla-repro volumio[32100]: info: CorePlayQueue::getTrackBlock Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::setRepeat null single undefined Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::pushState Aug 25 22:40:01 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::setRandom null Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreStateMachine::pushState Aug 25 22:40:01 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:01 spla-repro volumio[32100]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:02 spla-repro volumio[32100]: info: Setting Device type: Raspberry PI Aug 25 22:40:02 spla-repro volumio[32100]: 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: 2 Aug 25 22:40:02 spla-repro volumio[32100]: info: Completed loading Core Plugins Aug 25 22:40:02 spla-repro volumio[32100]: info: Preparing to generate the ALSA configuration file Aug 25 22:40:02 spla-repro volumio[32100]: info: Listing playlists Aug 25 22:40:02 spla-repro volumio[32100]: info: Listing playlists Aug 25 22:40:02 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787690398 101 Aug 25 22:40:02 spla-repro volumio[32100]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Aug 25 22:40:02 spla-repro volumio[32100]: Unable to parse: Aug 25 22:40:02 spla-repro volumio[32100]: Simple mixer control 'Master',0 Aug 25 22:40:02 spla-repro volumio[32100]: Capabilities: volume volume-joined Aug 25 22:40:02 spla-repro volumio[32100]: Playback channels: Mono Aug 25 22:40:02 spla-repro volumio[32100]: Capture channels: Mono Aug 25 22:40:02 spla-repro volumio[32100]: Limits: 0 - 248 Aug 25 22:40:02 spla-repro volumio[32100]: Mono: 112 [45%] Aug 25 22:40:02 spla-repro volumio[32100]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:40:02 spla-repro volumio[32100]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 22:40:02 spla-repro volumio[32100]: info: Discovery: Found device kuchyna-repro Aug 25 22:40:02 spla-repro volumio[32100]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 22:40:02 spla-repro volumio[32100]: 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 25 22:40:02 spla-repro volumio[32100]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 22:40:02 spla-repro volumio[32100]: info: Discovery: Found device kupelna-repro Aug 25 22:40:02 spla-repro volumio[32100]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 22:40:02 spla-repro volumio[32100]: 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 25 22:40:02 spla-repro volumio[32100]: Unable to parse: Aug 25 22:40:02 spla-repro volumio[32100]: Simple mixer control 'Master',0 Aug 25 22:40:02 spla-repro volumio[32100]: Capabilities: volume volume-joined Aug 25 22:40:02 spla-repro volumio[32100]: Playback channels: Mono Aug 25 22:40:02 spla-repro volumio[32100]: Capture channels: Mono Aug 25 22:40:02 spla-repro volumio[32100]: Limits: 0 - 248 Aug 25 22:40:02 spla-repro volumio[32100]: Mono: 112 [45%] Aug 25 22:40:02 spla-repro volumio[32100]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreStateMachine::pushState Aug 25 22:40:02 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:02 spla-repro volumio[32100]: 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: 6 Aug 25 22:40:02 spla-repro volumio[32100]: info: Asound.conf file unchanged, so no further update is needed Aug 25 22:40:02 spla-repro volumio[32100]: info: Output device has changed, restarting MPD Aug 25 22:40:02 spla-repro volumio[32100]: info: Output device has changed, restarting Shairport Sync Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:02 spla-repro sudo[32235]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:02 spla-repro sudo[32237]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:02 spla-repro volumio[32100]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:02 spla-repro sudo[32235]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:40:02 spla-repro sudo[32235]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:02 spla-repro sudo[32235]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:02 spla-repro sudo[32237]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:40:02 spla-repro volumio[32100]: info: ___________ START PLUGINS ___________ Aug 25 22:40:02 spla-repro sudo[32237]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:02 spla-repro volumio[32100]: info: ControllerMpd::onStart: Initializing MPD Aug 25 22:40:02 spla-repro volumio[32100]: info: Creating MPD Configuration file Aug 25 22:40:02 spla-repro sudo[32245]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:02 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 22:40:02 spla-repro sudo[32245]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 22:40:02 spla-repro sudo[32245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:02 spla-repro sudo[32247]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:02 spla-repro sudo[32247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:40:02 spla-repro sudo[32247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:02 spla-repro sudo[32247]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:02 spla-repro volumio[32100]: info: [1787690402661] CoreMusicLibrary::Adding element Mediálne servery Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:02 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:40:02 spla-repro sudo[32250]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:02 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:40:02 spla-repro systemd[1]: mpd.service: Consumed 4.711s CPU time. Aug 25 22:40:02 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:40:02 spla-repro sudo[32250]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:40:02 spla-repro sudo[32250]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:02 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:40:02 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:40:02 spla-repro volumio[32100]: info: UPNP Browser: Client initialized successfully Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:02 spla-repro volumio[32100]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:02 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:40:02 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:40:02 spla-repro volumio[32100]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:02 spla-repro volumio[32100]: info: [1787690402834] CoreMusicLibrary::Adding element Last_100 Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:02 spla-repro volumio[32100]: info: [1787690402844] CoreMusicLibrary::Adding element Webradio Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:02 spla-repro sudo[32245]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:40:02 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:40:02 spla-repro volumio[32100]: info: Initializing BBC Radios Aug 25 22:40:02 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:40:02 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:40:02 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:40:02 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:40:02 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:40:02 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:40:02 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:03 spla-repro volumio[32100]: info: Creating Spotify config file Aug 25 22:40:03 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:03 spla-repro sudo[32268]: root : unable to resolve host spla-repro: System error Aug 25 22:40:03 spla-repro sudo[32268]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:03 spla-repro sudo[32268]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 22:40:03 spla-repro sudo[32268]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 22:40:03 spla-repro sudo[32268]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:03 spla-repro volumio[32100]: info: Volumio Calling Home Aug 25 22:40:03 spla-repro volumio[32195]: Starting albumart workers Aug 25 22:40:03 spla-repro volumio[32197]: Starting albumart workers Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: Found device Spálňa-repro Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:04 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 22:40:04 spla-repro volumio[32100]: info: MPD Permissions set Aug 25 22:40:04 spla-repro volumio[32100]: info: MPD Permissions set Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:04 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: Found device Spálňa-repro Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:04 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:04 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 22:40:04 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:04 spla-repro volumio[32100]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 22:40:04 spla-repro volumio[32100]: info: Volumio called home Aug 25 22:40:04 spla-repro volumio[32100]: info: Spotify config file written Aug 25 22:40:04 spla-repro volumio[32193]: Starting albumart workers Aug 25 22:40:04 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:04 spla-repro go-librespot[32283]: go-librespot daemon starting... Aug 25 22:40:04 spla-repro sudo[32285]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:04 spla-repro sudo[32285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 22:40:04 spla-repro go-librespot[32286]: time="2026-08-25T22:40:04+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:04 spla-repro go-librespot[32286]: time="2026-08-25T22:40:04+02:00" level=debug msg="app state loaded" Aug 25 22:40:04 spla-repro sudo[32285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:04 spla-repro go-librespot[32286]: time="2026-08-25T22:40:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:04 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 25 22:40:04 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 25 22:40:04 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:04 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:04 spla-repro go-librespot[32296]: go-librespot daemon starting... Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro sudo[32285]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro go-librespot[32297]: time="2026-08-25T22:40:04+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:04 spla-repro go-librespot[32297]: time="2026-08-25T22:40:04+02:00" level=debug msg="app state loaded" Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:04 spla-repro volumio[32100]: info: No need to fix Spotify hosts Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:40:04 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:04 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:04 spla-repro go-librespot[32297]: time="2026-08-25T22:40:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:05 spla-repro volumio[32100]: 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: 6 Aug 25 22:40:05 spla-repro volumio[32100]: 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 25 22:40:05 spla-repro volumio[32100]: info: New Spotify access tokenBQBRHPJL82... Aug 25 22:40:05 spla-repro volumio[32100]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+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 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+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 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+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 25 22:40:05 spla-repro volumio[32100]: 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 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=info msg="zeroconf server listening on port 40367" Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:05 spla-repro volumio[32100]: info: Starting Shairport Sync Aug 25 22:40:05 spla-repro volumio[32100]: info: Starting Shairport Sync Aug 25 22:40:05 spla-repro volumio[32100]: info: Starting Shairport Sync Aug 25 22:40:05 spla-repro sudo[32323]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:05 spla-repro sudo[32323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:05 spla-repro volumio[32100]: 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 25 22:40:05 spla-repro sudo[32323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:05 spla-repro sudo[32326]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:05 spla-repro sudo[32326]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:05 spla-repro sudo[32326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=debug msg="obtained new client token: AAFstl16aSHE6eJPJeVcKTVg62ER09ISbvjG5MlQ39SBOGDO4+l8zV0qIMyN5q+QXxx/nMAv7Nw5P33c8Cf5ChH1SpVQzYk1YwqkpalqPEQIOKp0byHsleaDUucAdbYIB1boIhcvw4R1RRkxUku1KU176QzQMRy2R87TUvL4XTcEibL/kv8WWI0VaUUv/aC38r+DjZrtywRPsqm8qqki89/dKsWqmAwA9toszExieKV7/uPBTheBlAQAkQ==" Aug 25 22:40:05 spla-repro sudo[32327]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:05 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:40:05 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:40:05 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:05 spla-repro systemd[1]: shairport-sync.service: Consumed 1.879s CPU time. Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:05 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:05 spla-repro sudo[32327]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:05 spla-repro sudo[32327]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:05 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=debug msg="completed challenge" Aug 25 22:40:05 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:05 spla-repro sudo[32323]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:05 spla-repro volumio[32100]: info: Shairport-Sync Started Aug 25 22:40:05 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:40:05 spla-repro volumio[32100]: Error adding Membership: Error: addMembership EINVAL Aug 25 22:40:05 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:40:05 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:05 spla-repro go-librespot[32297]: time="2026-08-25T22:40:05+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:05 spla-repro volumio[32100]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 22:40:05 spla-repro volumio[32100]: info: Spotify Successfully logged in Aug 25 22:40:05 spla-repro volumio[32100]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:05 spla-repro volumio[32100]: info: [1787690405896] CoreMusicLibrary::Adding element Spotify Aug 25 22:40:05 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:05 spla-repro volumio[32100]: Cannot find translation for source Spotify Aug 25 22:40:05 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:05 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:05 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:05 spla-repro sudo[32326]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:05 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:40:05 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:40:05 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:05 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:06 spla-repro sudo[32327]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:06 spla-repro volumio[32100]: info: Shairport-Sync Started Aug 25 22:40:06 spla-repro volumio[32100]: info: Shairport-Sync Started Aug 25 22:40:06 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:06 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:07 spla-repro sudo[32375]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:07 spla-repro sudo[32377]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:07 spla-repro sudo[32375]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 22:40:07 spla-repro sudo[32375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:07 spla-repro sudo[32377]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 22:40:07 spla-repro sudo[32375]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:07 spla-repro sudo[32377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:07 spla-repro sudo[32377]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:07 spla-repro sudo[32380]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:07 spla-repro sudo[32380]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 22:40:07 spla-repro sudo[32380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:07 spla-repro sudo[32380]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:07 spla-repro volumio[32100]: info: Upmpdcli Daemon Started Aug 25 22:40:08 spla-repro mpd[32279]: 2026-08-25T22:40:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 22:40:08 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 22:40:08 spla-repro sudo[32250]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:08 spla-repro sudo[32237]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:08 spla-repro volumio[32100]: info: Completed starting Core Plugins Aug 25 22:40:08 spla-repro volumio[32100]: info: ------------------------------------------- Aug 25 22:40:08 spla-repro volumio[32100]: info: ----- MyVolumio plugins startup ---- Aug 25 22:40:08 spla-repro volumio[32100]: info: ------------------------------------------- Aug 25 22:40:08 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 22:40:08 spla-repro volumio[32100]: error: MPD error: The expression evaluated to a falsy value: Aug 25 22:40:08 spla-repro volumio[32100]: assert.ok(self.idling) Aug 25 22:40:08 spla-repro volumio[32100]: error: The expression evaluated to a falsy value: Aug 25 22:40:08 spla-repro volumio[32100]: assert.ok(self.idling) Aug 25 22:40:08 spla-repro volumio[32100]: error: updateQueue error: null Aug 25 22:40:08 spla-repro volumio[32100]: info: MPD running with PID32279 Aug 25 22:40:08 spla-repro volumio[32100]: ,establishing connection Aug 25 22:40:08 spla-repro volumio[32100]: error: updateQueue error: null Aug 25 22:40:08 spla-repro volumio[32100]: info: go-librespot daemon successfully initialized Aug 25 22:40:08 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:08.570+02:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Aug 25 22:40:08 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 25 22:40:08 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:09 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:09 spla-repro go-librespot[32387]: go-librespot daemon starting... Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=debug msg="app state loaded" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+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 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+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 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+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 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=info msg="zeroconf server listening on port 40397" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=debug msg="obtained new client token: AAEB7fqbcrc+S3ZjAZD+XqPnWNcH0AL5RjUlyPhWjhfNplMa+2MYittmaw3bhFDm3zYXYbQMb8Mx/JRv73PWk4gA559pt4bOCAF9IPBpdpyVPewjLHiR2rCzBsL6s5ihQfyP/I/Rv+sO3UwotvX5n5EXeoch/d/wxaLaDxdyLcZS0uWIn1gZwFOvxt+B2XGAfmv//+Ca3mxUrP5qPfxoAgQr0u2BfVpf5JHnVKM1OWb57N2NTm5OnK64rQ==" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=debug msg="completed challenge" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:09 spla-repro go-librespot[32388]: time="2026-08-25T22:40:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:09 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:09 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:11 spla-repro volumio[32100]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:11 spla-repro volumio[32100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:12 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 25 22:40:12 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:12 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:12 spla-repro go-librespot[32398]: go-librespot daemon starting... Aug 25 22:40:12 spla-repro go-librespot[32399]: time="2026-08-25T22:40:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:12 spla-repro go-librespot[32399]: time="2026-08-25T22:40:12+02:00" level=debug msg="app state loaded" Aug 25 22:40:12 spla-repro go-librespot[32399]: time="2026-08-25T22:40:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+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 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+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 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+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 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=info msg="zeroconf server listening on port 43703" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:13 spla-repro volumio[32100]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=debug msg="obtained new client token: AAFB5fESnybIe8ejRzArOpN//fnpjcbexmTaoKKCRtxmyWjjbC2W0UAi83oGqYncb8g+ZXDiM8A3dmSQapG+q9PcUOkVaKZeOIdlJa8rGaPmlHAerE1GatJFN+e+gny3p1jZqBtPOePDbacqvFZBLHggYhCovMCd6i3yOK06PCt3p42DDBeS5bxShV6es+//ggNP/wFGoRq3MZGaxdihXO7zzmSY8KQXVPeftiFmyN99ZavI/vAeqcs=" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=debug msg="completed challenge" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:13 spla-repro go-librespot[32399]: time="2026-08-25T22:40:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:13 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:13 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:14 spla-repro volumio[32100]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:14 spla-repro volumio[32100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:16 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:16 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:16 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 25 22:40:16 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:16 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:16 spla-repro go-librespot[32408]: go-librespot daemon starting... Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=debug msg="app state loaded" Aug 25 22:40:16 spla-repro volumio[32100]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 22:40:16 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+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 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+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 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+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 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=info msg="zeroconf server listening on port 46419" Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:16 spla-repro go-librespot[32409]: time="2026-08-25T22:40:16+02:00" level=debug msg="obtained new client token: AAHqM+RGr6RLbfmh2CZn46r+CDxL6ov+NGRO978SX18A2FGhfzYzR09UCauxuaa1rcAoeBdzpGzPjTk/DEuwKy7fMXDK+e7ICPl4LyDnRyO9Ufcqx6hxPbjRv9GfvBzRQhmeZKjvKuA8BVNt6ZXmc/VXHkE7QVVKNU9bSAvXGRcIddg0hfbvXbymoL2RxZRfprgUlKwSvrqtU1Rs+LenwVRro6ETPG/KSrzTItoViS8YDTr/bLmkhxAgZQ==" Aug 25 22:40:17 spla-repro go-librespot[32409]: time="2026-08-25T22:40:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:17 spla-repro go-librespot[32409]: time="2026-08-25T22:40:17+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:17 spla-repro go-librespot[32409]: time="2026-08-25T22:40:17+02:00" level=debug msg="completed challenge" Aug 25 22:40:17 spla-repro go-librespot[32409]: time="2026-08-25T22:40:17+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:17 spla-repro go-librespot[32409]: time="2026-08-25T22:40:17+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:17 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:17 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:17 spla-repro volumio[32100]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 22:40:17 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 22:40:17 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:17 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:17 spla-repro volumio[32100]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 22:40:17 spla-repro volumio[32100]: info: MyVolumio login type: Token Aug 25 22:40:17 spla-repro volumio[32100]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 22:40:17 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 22:40:18 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 22:40:18 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 22:40:18 spla-repro volumio[32100]: info: Streaming services startup Aug 25 22:40:18 spla-repro volumio[32100]: info: Starting Streaming Daemon Aug 25 22:40:18 spla-repro sudo[32433]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:18 spla-repro volumio[32100]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 22:40:18 spla-repro sudo[32433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 22:40:18 spla-repro sudo[32433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:18 spla-repro sudo[32433]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:18 spla-repro volumio[32100]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:18 spla-repro volumio[32100]: error: Cannot start Volumio Streaming Daemon Aug 25 22:40:18 spla-repro volumio[32100]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 22:40:18 spla-repro volumio[32100]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:18 spla-repro volumio[32100]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 22:40:18 spla-repro volumio[32100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:19 spla-repro volumio[32100]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 25 22:40:19 spla-repro volumio[32100]: info: MyVolumio token set successfully Aug 25 22:40:19 spla-repro volumio[32100]: info: MYVOLUMIO: Adding device Aug 25 22:40:19 spla-repro volumio[32100]: info: MYVOLUMIO: Evaluating Server Aug 25 22:40:20 spla-repro volumio[32100]: info: MyVolumio status changed Aug 25 22:40:20 spla-repro volumio[32100]: info: Streaming services startup Aug 25 22:40:20 spla-repro volumio[32100]: info: Starting Streaming Daemon Aug 25 22:40:20 spla-repro volumio[32100]: info: Removing browser output: myVolumio user plan is not superstar Aug 25 22:40:20 spla-repro volumio[32100]: info: Removing audio output: Aug 25 22:40:20 spla-repro volumio[32100]: info: Stoppping Tunnel 1 Aug 25 22:40:20 spla-repro sudo[32461]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:20 spla-repro sudo[32461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 22:40:20 spla-repro sudo[32461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:20 spla-repro sudo[32461]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:20 spla-repro sudo[32464]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:20 spla-repro volumio[32100]: error: Cannot start Volumio Streaming Daemon Aug 25 22:40:20 spla-repro sudo[32464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 25 22:40:20 spla-repro volumio[32100]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 22:40:20 spla-repro volumio[32100]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:20 spla-repro volumio[32100]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 22:40:20 spla-repro sudo[32464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 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 25 22:40:20 spla-repro sudo[32464]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:20 spla-repro volumio[32100]: info: Remote SSH Stopped Aug 25 22:40:20 spla-repro volumio[32100]: info: Setting Geolocation for MyVolumio to eu7 Aug 25 22:40:20 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:20 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:20 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:20 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 25 22:40:20 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:20 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:20 spla-repro go-librespot[32466]: go-librespot daemon starting... Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=debug msg="app state loaded" Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:20 spla-repro volumio[32100]: info: Successfully Added MyVolumio device Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+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 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+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 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+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 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=info msg="zeroconf server listening on port 43237" Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:20 spla-repro go-librespot[32467]: time="2026-08-25T22:40:20+02:00" level=debug msg="obtained new client token: AAGZP6oNoplW96VoNyYICMjzN8atRE0kxzEdiUpcKc/XwMp5wV11I7fPEMeB9EO6To3OLUCWTFL+PwPHKJAfOJnU/wi+l1yv0Q9bT+JNfIVq854VpMXoj4AflgcTJMKjBiwgDGs6WQ8CWDGawGemZY01vslZXMQvmVX8KPEqq6a0yVNlSQEtzn3kPyTIkMUOvLgOrc76OMkts2PljdCEtU+4jwgDH9YOC152EQvqwAU2t/cwTQlk+WNkUA==" Aug 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40:21+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 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40:21+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40:21+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40:21+02:00" level=debug msg="completed challenge" Aug 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40:21+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:21 spla-repro go-librespot[32467]: time="2026-08-25T22:40: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 25 22:40:21 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:21 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:21 spla-repro volumio[32100]: info: Updating MyVolumio device info Aug 25 22:40:21 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:21 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:21 spla-repro volumio[32100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:21 spla-repro volumio[32100]: info: Successfully Updated MyVolumio device Aug 25 22:40:21 spla-repro volumio[32100]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:21 spla-repro volumio[32100]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:24 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 25 22:40:24 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:24 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:24 spla-repro go-librespot[32476]: go-librespot daemon starting... Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=debug msg="app state loaded" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:24 spla-repro volumio[32100]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=debug msg="new websocket client" Aug 25 22:40:24 spla-repro volumio[32100]: info: Connection to go-librespot Websocket established Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+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 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+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 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=info msg="zeroconf server listening on port 39193" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=debug msg="obtained new client token: AAF3aHGX5/EyDYgQgZbW6E/MVgpGsXtMlxOQdSfOLN345Xaw+hlXPgv/oDTZWmnw5ekK5EwuqyEsvo5UjTcTe6eukN1YYg+N3HaA4yNBL6L2TpZs2rL3u8YQ9b2leNgyeehLUDqYtRLXhkvspRCqN+Gmsmo7j2M+834k9YKO+w4av44rEPft6hUwFebBsPKYy+x6qXppCdJm6+w0bcvh7LjtMf4fT/apou1iZjCEJXUcj9/0OtDESHneeg==" Aug 25 22:40:24 spla-repro go-librespot[32477]: time="2026-08-25T22:40:24+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:25 spla-repro go-librespot[32477]: time="2026-08-25T22:40:25+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:25 spla-repro go-librespot[32477]: time="2026-08-25T22:40:25+02:00" level=debug msg="completed challenge" Aug 25 22:40:25 spla-repro go-librespot[32477]: time="2026-08-25T22:40:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:25 spla-repro go-librespot[32477]: time="2026-08-25T22:40:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:25 spla-repro volumio[32100]: info: Connection to go-librespot Websocket closed Aug 25 22:40:25 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:25 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:26 spla-repro volumio[32100]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:26 spla-repro volumio[32100]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:26 spla-repro volumio[32100]: info: Listing playlists Aug 25 22:40:26 spla-repro volumio[32100]: info: Listing playlists Aug 25 22:40:27 spla-repro volumio[32100]: info: Getting Spotify volume Aug 25 22:40:27 spla-repro volumio[32100]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:40:27 spla-repro volumio[32100]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:27 spla-repro volumio[32100]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 22:40:27 spla-repro volumio[32100]: errno: -111, Aug 25 22:40:27 spla-repro volumio[32100]: code: 'ECONNREFUSED', Aug 25 22:40:27 spla-repro volumio[32100]: syscall: 'connect', Aug 25 22:40:27 spla-repro volumio[32100]: address: '127.0.0.1', Aug 25 22:40:27 spla-repro volumio[32100]: port: 9879, Aug 25 22:40:27 spla-repro volumio[32100]: response: undefined Aug 25 22:40:27 spla-repro volumio[32100]: } Aug 25 22:40:27 spla-repro volumio[32100]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:40:28 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 25 22:40:28 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:28 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:28 spla-repro go-librespot[32512]: go-librespot daemon starting... Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=debug msg="app state loaded" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+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 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+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 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+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 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=info msg="zeroconf server listening on port 46657" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:28 spla-repro sudo[32524]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:28 spla-repro sudo[32524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 22:39' Aug 25 22:40:28 spla-repro sudo[32524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=debug msg="obtained new client token: AAG5T+PpJHtY8uAF0FmScyZRqT0zz3WpLeQ42jXg+bbmIe8m+g8Uey0xQgdsxbXHdm+lkDtfjvZ6v7X1HGXgLueanOaTtK1lkMlAp3AksSOWuQRzhY2h7NrmvMk1TR8LKOYLi96Fkv/PH++2UMrv6Px6mtXjX4B0rUChstFWojkhwUmn12957i5lK0oNKm/EUEjJR+87VS/l+xs3zC2PU8Hx7KL4t0727177xUrAIc77/5EQSplNF2755w==" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=debug msg="completed challenge" Aug 25 22:40:28 spla-repro sudo[32524]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:28 spla-repro volumio[32100]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:28 spla-repro go-librespot[32513]: time="2026-08-25T22:40:28+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:28 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:28] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 25 22:40:28 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:28] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 25 22:40:28 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:28 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:28.937+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 25 22:40:28 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:28.939+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 22:40:28 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 25 22:40:28 spla-repro systemd[1]: volumio.service: Consumed 29.607s CPU time. Aug 25 22:40:29 spla-repro go-librespot[32513]: time="2026-08-25T22:40:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:29 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 22:40:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:29 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:29 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 22:40:29 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6013. Aug 25 22:40:29 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 22:40:29 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 25 22:40:29 spla-repro systemd[1]: volumio.service: Consumed 29.607s CPU time. Aug 25 22:40:29 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 25 22:40:29 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 22:40:29 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:29.940+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 22:40:31 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:31 spla-repro volumio[32536]: info: ----- Volumio3 ---- Aug 25 22:40:31 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:31 spla-repro volumio[32536]: info: ----- System startup ---- Aug 25 22:40:31 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:32 spla-repro volumio[32536]: info: MYVOLUMIO Environment detected Aug 25 22:40:32 spla-repro volumio[32536]: info: Plugin folders cleanup Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning into folder /volumio/app/plugins/ Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category audio_interface Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category miscellanea Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category music_service Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category plugins.json Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category system_controller Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category user_interface Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning into folder /data/plugins/ Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category audio_interface Aug 25 22:40:32 spla-repro volumio[32536]: info: Scanning category music_service Aug 25 22:40:32 spla-repro volumio[32536]: info: Plugin folders cleanup completed Aug 25 22:40:32 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:32 spla-repro volumio[32536]: info: ----- Core plugins startup ---- Aug 25 22:40:32 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:32 spla-repro volumio[32536]: info: Loading plugins from folder /volumio/app/plugins/ Aug 25 22:40:32 spla-repro volumio[32536]: info: Adding plugin upnp to MyMusic Plugins Aug 25 22:40:32 spla-repro volumio[32536]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 25 22:40:32 spla-repro volumio[32536]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 25 22:40:32 spla-repro volumio[32536]: info: Loading plugins from folder /data/plugins/ Aug 25 22:40:32 spla-repro volumio[32536]: info: Loading plugin "system"... Aug 25 22:40:32 spla-repro volumio[32536]: info: Loading plugin "appearance"... Aug 25 22:40:32 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 22:40:32 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:32 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:32 spla-repro go-librespot[32564]: go-librespot daemon starting... Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=debug msg="app state loaded" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+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 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+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 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+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 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=info msg="zeroconf server listening on port 36041" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=debug msg="obtained new client token: AAFZZ2jth/Y40XErz/hNRLraDlzpe9Nr4+cn1TOUIOlLL4fu8TPwbIoYXE+iFsfqrTsTBkKQF8jyIpxUAubFCYijEKFm1nYkbhFtdi4uk1T4nzbEW7lxewN6hhDX0Bvb6pig2exgPzKzB5gbZbQ7wHOAeTQM3DmMmg0FO9P5CcY47Qh6AHS9Q6iQUVStBjO0iHF5aohZxovwtausSTfxyFwrIZ2/JYWzDo4bofY89S36wWaCHTmnNJhfpg==" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=debug msg="completed challenge" Aug 25 22:40:32 spla-repro go-librespot[32565]: time="2026-08-25T22:40:32+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:33 spla-repro go-librespot[32565]: time="2026-08-25T22:40: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 25 22:40:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "network"... Aug 25 22:40:33 spla-repro volumio[32536]: info: Refreshing Cached IP Addresses Aug 25 22:40:33 spla-repro sudo[32575]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:33 spla-repro sudo[32577]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:33 spla-repro sudo[32575]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 22:40:33 spla-repro sudo[32575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "services"... Aug 25 22:40:33 spla-repro sudo[32577]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 22:40:33 spla-repro sudo[32577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "volumio5onboarding"... Aug 25 22:40:33 spla-repro sudo[32577]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:33 spla-repro sudo[32575]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:33 spla-repro sudo[32584]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "alsa_controller"... Aug 25 22:40:33 spla-repro sudo[32584]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 25 22:40:33 spla-repro sudo[32584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:33 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "wizard"... Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "networkfs"... Aug 25 22:40:33 spla-repro volumio[32536]: info: Starting Udev Watcher for removable devices Aug 25 22:40:33 spla-repro volumio[32536]: info: Ignoring mount for partition: boot Aug 25 22:40:33 spla-repro volumio[32536]: info: Ignoring mount for partition: volumio Aug 25 22:40:33 spla-repro volumio[32536]: info: Ignoring mount for partition: volumio_data Aug 25 22:40:33 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "volumio_command_line_client"... Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "upnp"... Aug 25 22:40:33 spla-repro volumio[32536]: info: [1787690433586] Starting Upmpd Daemon Aug 25 22:40:33 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "my_music"... Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "mpd"... Aug 25 22:40:33 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:33] [connect] Successful connection Aug 25 22:40:33 spla-repro volumio[32536]: info: Loading plugin "upnp_browser"... Aug 25 22:40:34 spla-repro sudo[32584]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:35 spla-repro volumio[32536]: info: Starting UPNP Browser Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "alarm-clock"... Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "airplay_emulation"... Aug 25 22:40:35 spla-repro volumio[32536]: info: Starting Shairport Sync Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "last_100"... Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "webradio"... Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "i2s_dacs"... Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "volumiodiscovery"... Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** For more information see Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:40:35 spla-repro volumio[32536]: *** WARNING *** For more information see Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** For more information see Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:40:35 spla-repro node[32536]: *** WARNING *** For more information see Aug 25 22:40:35 spla-repro volumio[32536]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 25 22:40:35 spla-repro volumio[32536]: info: Discovery: Started advertising with name: Spálňa-repro Aug 25 22:40:35 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:40:35 spla-repro volumio[32536]: info: Loading plugin "spop"... Aug 25 22:40:36 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 22:40:36 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:36 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:36 spla-repro go-librespot[32610]: go-librespot daemon starting... Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=debug msg="app state loaded" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+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 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+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 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=info msg="zeroconf server listening on port 32987" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=debug msg="obtained new client token: AAGbK1faKhi/GbdXK5igrzqTj4AwbIznHcNSPkyL0V6ZLGIpXaedRbdELZPida/1JEJUeERb7l0sTUI4vzEMwjH2+vX69hVmTy0BQGCkztS2ChinuUuzj2AVkQ1WpEHt/9xxbyLbGSI6txONyWMumGPAZu4PYismq/l8+D6OK3BiwLoE7f91FGTMHCQpMHlkYSewGuiWMQeKF687/SrNjOGG7eaYtAW1jB3JS0Jh32CybIbS187f8qDiuw==" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=debug msg="completed challenge" Aug 25 22:40:36 spla-repro go-librespot[32611]: time="2026-08-25T22:40:36+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "outputs"... Aug 25 22:40:37 spla-repro go-librespot[32611]: time="2026-08-25T22:40: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 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "albumart"... Aug 25 22:40:37 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:37 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:37 spla-repro volumio[32536]: info: Plugin example_plugin is not enabled Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "inputs"... Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "updater_comm"... Aug 25 22:40:37 spla-repro volumio[32536]: info: Plugin mpdemulation is not enabled Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "rest_api"... Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading plugin "websocket"... Aug 25 22:40:37 spla-repro volumio[32536]: info: Starting Socket.io Server version 1.7.4 Aug 25 22:40:37 spla-repro volumio[32536]: info: Plugin fusiondsp is not enabled Aug 25 22:40:37 spla-repro volumio[32536]: info: Loading i18n strings for locale sk Aug 25 22:40:37 spla-repro volumio[32536]: Updating browse sources language Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::initPlayerControls Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: Express server listening on port 3000 Aug 25 22:40:37 spla-repro volumio[32536]: [Metrics] WebUI: 6s 680.96ms Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::resetVolumioState Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::getcurrentVolume Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:40:37 spla-repro volumio[32536]: info: Cannot read play queue from file Aug 25 22:40:37 spla-repro volumio[32536]: info: Volumio Network Manager: Network status updated: 1 Aug 25 22:40:37 spla-repro volumio[32536]: 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 25 22:40:37 spla-repro volumio[32620]: Forking 3 albumart workers Aug 25 22:40:37 spla-repro volumio[32536]: Unable to parse: Aug 25 22:40:37 spla-repro volumio[32536]: Simple mixer control 'Master',0 Aug 25 22:40:37 spla-repro volumio[32536]: Capabilities: volume volume-joined Aug 25 22:40:37 spla-repro volumio[32536]: Playback channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Capture channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Limits: 0 - 248 Aug 25 22:40:37 spla-repro volumio[32536]: Mono: 112 [45%] Aug 25 22:40:37 spla-repro volumio[32536]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:40:37 spla-repro volumio[32536]: 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 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:37 spla-repro volumio[32536]: 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: 2 Aug 25 22:40:37 spla-repro volumio[32536]: Unable to parse: Aug 25 22:40:37 spla-repro volumio[32536]: Simple mixer control 'Master',0 Aug 25 22:40:37 spla-repro volumio[32536]: Capabilities: volume volume-joined Aug 25 22:40:37 spla-repro volumio[32536]: Playback channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Capture channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Limits: 0 - 248 Aug 25 22:40:37 spla-repro volumio[32536]: Mono: 112 [45%] Aug 25 22:40:37 spla-repro volumio[32536]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::pushState Aug 25 22:40:37 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::updateTrackBlock Aug 25 22:40:37 spla-repro volumio[32536]: info: CorePlayQueue::getTrackBlock Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::setRepeat null single undefined Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::pushState Aug 25 22:40:37 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::setRandom null Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreStateMachine::pushState Aug 25 22:40:37 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:37 spla-repro volumio[32536]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:37 spla-repro volumio[32536]: info: Setting Device type: Raspberry PI Aug 25 22:40:37 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787690433 101 Aug 25 22:40:37 spla-repro volumio[32536]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Aug 25 22:40:37 spla-repro volumio[32536]: info: Completed loading Core Plugins Aug 25 22:40:37 spla-repro volumio[32536]: info: Preparing to generate the ALSA configuration file Aug 25 22:40:37 spla-repro volumio[32536]: Unable to parse: Aug 25 22:40:37 spla-repro volumio[32536]: Simple mixer control 'Master',0 Aug 25 22:40:37 spla-repro volumio[32536]: Capabilities: volume volume-joined Aug 25 22:40:37 spla-repro volumio[32536]: Playback channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Capture channels: Mono Aug 25 22:40:37 spla-repro volumio[32536]: Limits: 0 - 248 Aug 25 22:40:37 spla-repro volumio[32536]: Mono: 112 [45%] Aug 25 22:40:37 spla-repro volumio[32536]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:38 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:38 spla-repro volumio[32536]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 22:40:38 spla-repro volumio[32536]: info: Discovery: Found device kuchyna-repro Aug 25 22:40:38 spla-repro volumio[32536]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 22:40:38 spla-repro volumio[32536]: 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 25 22:40:38 spla-repro volumio[32536]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 22:40:38 spla-repro volumio[32536]: info: Discovery: Found device kupelna-repro Aug 25 22:40:38 spla-repro volumio[32536]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 22:40:38 spla-repro volumio[32536]: 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 25 22:40:38 spla-repro volumio[32536]: Unable to parse: Aug 25 22:40:38 spla-repro volumio[32536]: Simple mixer control 'Master',0 Aug 25 22:40:38 spla-repro volumio[32536]: Capabilities: volume volume-joined Aug 25 22:40:38 spla-repro volumio[32536]: Playback channels: Mono Aug 25 22:40:38 spla-repro volumio[32536]: Capture channels: Mono Aug 25 22:40:38 spla-repro volumio[32536]: Limits: 0 - 248 Aug 25 22:40:38 spla-repro volumio[32536]: Mono: 112 [45%] Aug 25 22:40:38 spla-repro volumio[32536]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreStateMachine::pushState Aug 25 22:40:38 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::volumioPushState Aug 25 22:40:38 spla-repro volumio[32536]: 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: 6 Aug 25 22:40:38 spla-repro volumio[32536]: info: Asound.conf file unchanged, so no further update is needed Aug 25 22:40:38 spla-repro volumio[32536]: info: Output device has changed, restarting MPD Aug 25 22:40:38 spla-repro volumio[32536]: info: Output device has changed, restarting Shairport Sync Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:38 spla-repro sudo[32677]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:38 spla-repro sudo[32677]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:40:38 spla-repro sudo[32677]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:38 spla-repro sudo[32677]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:38 spla-repro sudo[32678]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:38 spla-repro sudo[32678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:40:38 spla-repro sudo[32678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:38 spla-repro volumio[32536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:38 spla-repro volumio[32536]: info: ___________ START PLUGINS ___________ Aug 25 22:40:38 spla-repro volumio[32536]: info: ControllerMpd::onStart: Initializing MPD Aug 25 22:40:38 spla-repro volumio[32536]: info: Creating MPD Configuration file Aug 25 22:40:38 spla-repro sudo[32686]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:38 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 22:40:38 spla-repro sudo[32686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 22:40:38 spla-repro sudo[32686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:38 spla-repro sudo[32688]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:38 spla-repro sudo[32688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:40:38 spla-repro sudo[32688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:38 spla-repro sudo[32688]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:38 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:40:38 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:40:38 spla-repro systemd[1]: mpd.service: Consumed 4.832s CPU time. Aug 25 22:40:38 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:40:38 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:40:38 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:38 spla-repro volumio[32536]: info: [1787690438525] CoreMusicLibrary::Adding element Mediálne servery Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:38 spla-repro sudo[32692]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:38 spla-repro sudo[32692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:40:38 spla-repro sudo[32692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:38 spla-repro volumio[32536]: info: UPNP Browser: Client initialized successfully Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:38 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:40:38 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:40:38 spla-repro volumio[32536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:38 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:40:38 spla-repro volumio[32536]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:40:38 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:38 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:40:38 spla-repro volumio[32536]: info: [1787690438749] CoreMusicLibrary::Adding element Last_100 Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:38 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:40:38 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:38 spla-repro volumio[32536]: info: [1787690438770] CoreMusicLibrary::Adding element Webradio Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:40:38 spla-repro volumio[32536]: info: Initializing BBC Radios Aug 25 22:40:38 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:40:38 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:40:38 spla-repro sudo[32686]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:38 spla-repro volumio[32536]: info: Creating Spotify config file Aug 25 22:40:38 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:39 spla-repro sudo[32713]: root : unable to resolve host spla-repro: System error Aug 25 22:40:39 spla-repro sudo[32713]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:39 spla-repro sudo[32713]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 22:40:39 spla-repro sudo[32713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 22:40:39 spla-repro sudo[32713]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:39 spla-repro volumio[32636]: Starting albumart workers Aug 25 22:40:39 spla-repro volumio[32536]: info: Volumio Calling Home Aug 25 22:40:39 spla-repro volumio[32638]: Starting albumart workers Aug 25 22:40:39 spla-repro volumio[32635]: Starting albumart workers Aug 25 22:40:40 spla-repro volumio[32536]: 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: 6 Aug 25 22:40:40 spla-repro volumio[32536]: info: Received Get System Info Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 22:40:40 spla-repro volumio[32536]: info: Discovery: Getting this device information Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:40 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 22:40:40 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 25 22:40:40 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:40 spla-repro go-librespot[32724]: go-librespot daemon starting... Aug 25 22:40:40 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:40 spla-repro go-librespot[32725]: time="2026-08-25T22:40:40+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 22:40:40 spla-repro volumio[32536]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:40:40 spla-repro volumio[32536]: info: Discovery: Found device Spálňa-repro Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:40 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:40 spla-repro volumio[32536]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 22:40:40 spla-repro go-librespot[32725]: time="2026-08-25T22:40:40+02:00" level=info msg="zeroconf server listening on port 36427" Aug 25 22:40:40 spla-repro go-librespot[32725]: time="2026-08-25T22:40:40+02:00" level=info msg="using built-in mDNS responder" Aug 25 22:40:40 spla-repro volumio[32536]: info: MPD Permissions set Aug 25 22:40:40 spla-repro volumio[32536]: info: MPD Permissions set Aug 25 22:40:40 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:41 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:41 spla-repro volumio[32536]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:40:41 spla-repro volumio[32536]: info: Discovery: Found device Spálňa-repro Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:41 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:41 spla-repro volumio[32536]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 22:40:41 spla-repro volumio[32536]: info: Volumio called home Aug 25 22:40:41 spla-repro volumio[32536]: info: Spotify config file written Aug 25 22:40:41 spla-repro sudo[32748]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:41 spla-repro sudo[32748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 22:40:41 spla-repro sudo[32748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:41 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 25 22:40:41 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 25 22:40:41 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:41 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:41.322+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 25 22:40:41 spla-repro go-librespot[32750]: go-librespot daemon starting... Aug 25 22:40:41 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro sudo[32748]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+02:00" level=debug msg="app state loaded" Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:40:41 spla-repro volumio[32536]: info: No need to fix Spotify hosts Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:41 spla-repro volumio[32536]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:40:41 spla-repro volumio[32536]: info: New Spotify access tokenBQA0NlbqIG... Aug 25 22:40:41 spla-repro volumio[32536]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 22:40:41 spla-repro volumio[32536]: info: Starting Shairport Sync Aug 25 22:40:41 spla-repro volumio[32536]: info: Starting Shairport Sync Aug 25 22:40:41 spla-repro volumio[32536]: info: Starting Shairport Sync Aug 25 22:40:41 spla-repro sudo[310]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:41 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:41 spla-repro sudo[312]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:41 spla-repro sudo[310]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:41 spla-repro sudo[310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:41 spla-repro sudo[312]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:41 spla-repro sudo[312]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:41 spla-repro sudo[314]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:41 spla-repro sudo[314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:40:41 spla-repro sudo[314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+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 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+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 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+02:00" level=info msg="zeroconf server listening on port 41423" Aug 25 22:40:41 spla-repro go-librespot[32756]: time="2026-08-25T22:40:41+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:41 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:41 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:41 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:40:41 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:40:41 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:41 spla-repro systemd[1]: shairport-sync.service: Consumed 1.976s CPU time. Aug 25 22:40:42 spla-repro volumio[32536]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 22:40:42 spla-repro volumio[32536]: info: Spotify Successfully logged in Aug 25 22:40:42 spla-repro volumio[32536]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:40:42 spla-repro volumio[32536]: info: [1787690442048] CoreMusicLibrary::Adding element Spotify Aug 25 22:40:42 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:40:42 spla-repro volumio[32536]: Cannot find translation for source Spotify Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+02:00" level=debug msg="obtained new client token: AAGvC/7p/kbORtl3yuWdg0D0kSAIny5Y9F4ojAbZ8KTXHouF7TmMtzTtW/dw8QrPkJtRTsF8J5Gks7B9jnpxiK0UDYP3fGjfakfPSJgFxU0CNZOxxul/ofBapFdXYYGo8ZqIz40I00lrB6E5/UxwoRLnLHsuRgywz9WwEMeDfPJXmuqfMDo3JCpSl9+ZhveA0zOzQtgLAmaif0TYJuhLk6BwNZ2s4r3in5kpa7+JLGgzlXppdFj8+/o=" Aug 25 22:40:42 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:40:42 spla-repro sudo[310]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:42 spla-repro sudo[312]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+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 25 22:40:42 spla-repro volumio[32536]: info: Shairport-Sync Started Aug 25 22:40:42 spla-repro volumio[32536]: Error adding Membership: Error: addMembership EINVAL Aug 25 22:40:42 spla-repro volumio[32536]: info: Shairport-Sync Started Aug 25 22:40:42 spla-repro sudo[314]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 22:40:42 spla-repro volumio[32536]: info: Shairport-Sync Started Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+02:00" level=debug msg="completed challenge" Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40:42+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:42 spla-repro go-librespot[32756]: time="2026-08-25T22:40: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 25 22:40:42 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:42 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:43 spla-repro sudo[350]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:43 spla-repro sudo[350]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 22:40:43 spla-repro sudo[350]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:43 spla-repro sudo[350]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:43 spla-repro sudo[352]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:43 spla-repro sudo[352]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 22:40:43 spla-repro sudo[352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:43 spla-repro sudo[352]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:43 spla-repro sudo[355]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:43 spla-repro sudo[355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 22:40:43 spla-repro sudo[355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:43 spla-repro sudo[355]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:43 spla-repro volumio[32536]: info: Upmpdcli Daemon Started Aug 25 22:40:43 spla-repro mpd[32720]: 2026-08-25T22:40:43 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 22:40:43 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 22:40:43 spla-repro sudo[32678]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:43 spla-repro sudo[32692]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:43 spla-repro volumio[32536]: info: Completed starting Core Plugins Aug 25 22:40:43 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:43 spla-repro volumio[32536]: info: ----- MyVolumio plugins startup ---- Aug 25 22:40:43 spla-repro volumio[32536]: info: ------------------------------------------- Aug 25 22:40:43 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 22:40:44 spla-repro volumio[32536]: error: MPD error: The expression evaluated to a falsy value: Aug 25 22:40:44 spla-repro volumio[32536]: assert.ok(self.idling) Aug 25 22:40:44 spla-repro volumio[32536]: error: The expression evaluated to a falsy value: Aug 25 22:40:44 spla-repro volumio[32536]: assert.ok(self.idling) Aug 25 22:40:44 spla-repro volumio[32536]: info: MPD running with PID32720 Aug 25 22:40:44 spla-repro volumio[32536]: ,establishing connection Aug 25 22:40:44 spla-repro volumio[32536]: error: updateQueue error: null Aug 25 22:40:44 spla-repro volumio[32536]: error: updateQueue error: null Aug 25 22:40:44 spla-repro volumio[32536]: info: go-librespot daemon successfully initialized Aug 25 22:40:45 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 25 22:40:45 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:45 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:45 spla-repro go-librespot[364]: go-librespot daemon starting... Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=debug msg="app state loaded" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40: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-gew4.spotify.com:80]" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+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 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+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 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=info msg="zeroconf server listening on port 41981" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:45 spla-repro go-librespot[365]: time="2026-08-25T22:40:45+02:00" level=debug msg="obtained new client token: AAFnovZk4BupEf1yTwohTizrtDGtxfaL4P/0KKqhyQZRVXxxWh+0oifIcWj836jKzUEa5IJxZrshTJz0Gua11r8C3Eq3T1RgFn2ngl0x/NsQuBzebrUe8eS7hVC2x/UpgkbzdtJJ1aTosge2N7s/bbQndyNEDQr1t6+Z9DQBz0ed+0PLv0DPsrX2FL53ByWR4b/fSwDDuiVdKxzNhoy5BLU7QuiYS5vjssK6G+/OA2tGxHm3Lh2qz8vx7A==" Aug 25 22:40:46 spla-repro go-librespot[365]: time="2026-08-25T22:40:46+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:46 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:46 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:46 spla-repro volumio[32536]: info: Listing playlists Aug 25 22:40:46 spla-repro volumio[32536]: info: Listing playlists Aug 25 22:40:47 spla-repro go-librespot[365]: time="2026-08-25T22:40:47+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:47 spla-repro go-librespot[365]: time="2026-08-25T22:40:47+02:00" level=debug msg="completed challenge" Aug 25 22:40:47 spla-repro go-librespot[365]: time="2026-08-25T22:40:47+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:47 spla-repro go-librespot[365]: time="2026-08-25T22:40:47+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:47 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:47 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:47 spla-repro volumio[32536]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:47 spla-repro volumio[32536]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:40:48 spla-repro volumio[32536]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 22:40:50 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 25 22:40:50 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:50 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:50 spla-repro go-librespot[374]: go-librespot daemon starting... Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=debug msg="app state loaded" Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:50 spla-repro volumio[32536]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=debug msg="new websocket client" Aug 25 22:40:50 spla-repro volumio[32536]: info: Connection to go-librespot Websocket established Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+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 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+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 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+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 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=info msg="zeroconf server listening on port 46875" Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=debug msg="obtained new client token: AAFAo3JRA8uxkjKywrpOUKyL1W7Z3oY1csG0aD4IJ//51Xuzg44v12dbkkvvLzpkSC3v71vGEJcRPwJh6qZy2wOq5xgEF0ug5TuDIXDKovaHapkMUjYo/gDJSxXQdivB6XuWe1lF6iEQMU6PU7QUf4i49MdoOXcInHzHPOK0qHeTtN3uZHcd4/lzazzb1Do2/kY9Fpa71YDuXl0RPivrXJlDEJuNke6Rr3wi5tXlo0Q+FmREcXlOalSX+A==" Aug 25 22:40:50 spla-repro go-librespot[375]: time="2026-08-25T22:40:50+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:51 spla-repro go-librespot[375]: time="2026-08-25T22:40:51+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:51 spla-repro go-librespot[375]: time="2026-08-25T22:40:51+02:00" level=debug msg="completed challenge" Aug 25 22:40:51 spla-repro go-librespot[375]: time="2026-08-25T22:40:51+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:51 spla-repro go-librespot[375]: time="2026-08-25T22:40: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 25 22:40:51 spla-repro volumio[32536]: info: Connection to go-librespot Websocket closed Aug 25 22:40:51 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:51 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 22:40:52 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 22:40:53 spla-repro volumio[32536]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 22:40:53 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 22:40:53 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:53 spla-repro volumio[32536]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:40:53 spla-repro volumio[32536]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 22:40:53 spla-repro volumio[32536]: info: MyVolumio login type: Token Aug 25 22:40:53 spla-repro volumio[32536]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 22:40:53 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 22:40:54 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 25 22:40:54 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:54 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:54 spla-repro go-librespot[404]: go-librespot daemon starting... Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=debug msg="app state loaded" Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:54 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 22:40:54 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 22:40:54 spla-repro volumio[32536]: info: Streaming services startup Aug 25 22:40:54 spla-repro volumio[32536]: info: Starting Streaming Daemon Aug 25 22:40:54 spla-repro sudo[414]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:54 spla-repro volumio[32536]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 22:40:54 spla-repro sudo[414]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 22:40:54 spla-repro sudo[414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:54 spla-repro sudo[414]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:54 spla-repro volumio[32536]: info: Getting Spotify volume Aug 25 22:40:54 spla-repro volumio[32536]: info: Initializing connection to go-librespot Websocket Aug 25 22:40:54 spla-repro volumio[32536]: error: Cannot start Volumio Streaming Daemon Aug 25 22:40:54 spla-repro volumio[32536]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 22:40:54 spla-repro volumio[32536]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:54 spla-repro volumio[32536]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=debug msg="new websocket client" Aug 25 22:40:54 spla-repro volumio[32536]: 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 25 22:40:54 spla-repro volumio[32536]: info: Connection to go-librespot Websocket established Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+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 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+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 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+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 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=info msg="zeroconf server listening on port 40743" Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:54 spla-repro volumio[32536]: info: CoreCommandRouter::volumioGetState Aug 25 22:40:54 spla-repro volumio[32536]: info: CorePlayQueue::getTrack 0 Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=debug msg="obtained new client token: AAHw2OOCjhF/66CTir9vb5+TXrr8tdipW0S7NdBP9h0VoOeVwlGWnkXSI0CBagFRT8tONtIdw8iXo2Nbr2bcmEa6zC2KDnfQ0og5V4dqdlaow5orSYjUdivhDE2YSKUiTZgNAE+iAO+/EVCryXGAbOLjlWLuDYDfu2lQJn2tFgClCsGJKqcV5/+Mrd7JpI6ocwxvqQI3giBtv8nNt1bhcaIVetMsPDA8/07FF8sFj9O9ZrFT6JgOZy2Wbw==" Aug 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+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 25 22:40:54 spla-repro go-librespot[405]: time="2026-08-25T22:40:54+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 22:40:55 spla-repro volumio[32536]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 25 22:40:55 spla-repro go-librespot[405]: time="2026-08-25T22:40:55+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:55 spla-repro go-librespot[405]: time="2026-08-25T22:40:55+02:00" level=debug msg="completed challenge" Aug 25 22:40:55 spla-repro go-librespot[405]: time="2026-08-25T22:40:55+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:55 spla-repro volumio[32536]: info: MyVolumio token set successfully Aug 25 22:40:55 spla-repro volumio[32536]: info: MYVOLUMIO: Adding device Aug 25 22:40:55 spla-repro volumio[32536]: info: MYVOLUMIO: Evaluating Server Aug 25 22:40:55 spla-repro go-librespot[405]: time="2026-08-25T22:40:55+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:55 spla-repro volumio[32536]: info: Connection to go-librespot Websocket closed Aug 25 22:40:55 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:55 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:55 spla-repro volumio[32536]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:40:55 spla-repro volumio[32536]: Error: socket hang up Aug 25 22:40:55 spla-repro volumio[32536]: at connResetException (node:internal/errors:720:14) Aug 25 22:40:55 spla-repro volumio[32536]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 25 22:40:55 spla-repro volumio[32536]: at Socket.emit (node:events:526:35) Aug 25 22:40:55 spla-repro volumio[32536]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 25 22:40:55 spla-repro volumio[32536]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 25 22:40:55 spla-repro volumio[32536]: code: 'ECONNRESET', Aug 25 22:40:55 spla-repro volumio[32536]: response: undefined Aug 25 22:40:55 spla-repro volumio[32536]: } Aug 25 22:40:55 spla-repro volumio[32536]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:40:56 spla-repro sudo[438]: volumio : unable to resolve host spla-repro: System error Aug 25 22:40:56 spla-repro sudo[438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 22:39' Aug 25 22:40:56 spla-repro sudo[438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:40:56 spla-repro sudo[438]: pam_unix(sudo:session): session closed for user root Aug 25 22:40:57 spla-repro volumio[32536]: sudo: unable to resolve host spla-repro: System error Aug 25 22:40:57 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:57] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 25 22:40:57 spla-repro volumio-remote-updater[725]: [2026-08-25 22:40:57] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 25 22:40:57 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:57.181+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 25 22:40:57 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:57 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:57.184+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 22:40:57 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 25 22:40:57 spla-repro systemd[1]: volumio.service: Consumed 28.930s CPU time. Aug 25 22:40:57 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 22:40:57 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 22:40:57 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6014. Aug 25 22:40:57 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 22:40:57 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 25 22:40:57 spla-repro systemd[1]: volumio.service: Consumed 28.930s CPU time. Aug 25 22:40:57 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 25 22:40:57 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 22:40:58 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:40:58.186+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 22:40:58 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 25 22:40:58 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:58 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:40:58 spla-repro go-librespot[470]: go-librespot daemon starting... Aug 25 22:40:58 spla-repro go-librespot[471]: time="2026-08-25T22:40:58+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:40:58 spla-repro go-librespot[471]: time="2026-08-25T22:40:58+02:00" level=debug msg="app state loaded" Aug 25 22:40:58 spla-repro go-librespot[471]: time="2026-08-25T22:40:58+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+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 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+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 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=info msg="zeroconf server listening on port 38445" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=debug msg="obtained new client token: AAEJGD7M6lnXPdjdAllf99ffQfKGQltA6wDL0YspSPSE9TCJiHvL6p8t25tLekI65DoQPqmwQKuyNMm+l81noEfnSadvferFRVAgJLIHTXteDfs4EclzlSIxvZJkueDnFGUqd7UwLcqQzEAggfDQ8njn3cSYzdJ9r3egHb2sT1nd9ZGkLCr3mrmpk4Ysjc9/oIYpe4+VV7hT4Ws2fQIdk8gVK3hTz0ueC3PQzCBois+ndX2PycE7Bn4=" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=debug msg="completed keyexchange" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=debug msg="completed challenge" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:40:59 spla-repro go-librespot[471]: time="2026-08-25T22:40:59+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:40:59 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:40:59 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:40:59 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:40:59 spla-repro volumio[454]: info: ----- Volumio3 ---- Aug 25 22:40:59 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:40:59 spla-repro volumio[454]: info: ----- System startup ---- Aug 25 22:40:59 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:41:00 spla-repro volumio[454]: info: MYVOLUMIO Environment detected Aug 25 22:41:00 spla-repro volumio[454]: info: Plugin folders cleanup Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning into folder /volumio/app/plugins/ Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category audio_interface Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category miscellanea Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category music_service Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category plugins.json Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category system_controller Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category user_interface Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning into folder /data/plugins/ Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category audio_interface Aug 25 22:41:00 spla-repro volumio[454]: info: Scanning category music_service Aug 25 22:41:00 spla-repro volumio[454]: info: Plugin folders cleanup completed Aug 25 22:41:00 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:41:00 spla-repro volumio[454]: info: ----- Core plugins startup ---- Aug 25 22:41:00 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:41:00 spla-repro volumio[454]: info: Loading plugins from folder /volumio/app/plugins/ Aug 25 22:41:00 spla-repro volumio[454]: info: Adding plugin upnp to MyMusic Plugins Aug 25 22:41:00 spla-repro volumio[454]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 25 22:41:00 spla-repro volumio[454]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 25 22:41:00 spla-repro volumio[454]: info: Loading plugins from folder /data/plugins/ Aug 25 22:41:00 spla-repro volumio[454]: info: Loading plugin "system"... Aug 25 22:41:00 spla-repro volumio[454]: info: Loading plugin "appearance"... Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "network"... Aug 25 22:41:01 spla-repro volumio[454]: info: Refreshing Cached IP Addresses Aug 25 22:41:01 spla-repro sudo[495]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:01 spla-repro sudo[497]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:01 spla-repro sudo[495]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "services"... Aug 25 22:41:01 spla-repro sudo[495]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:01 spla-repro sudo[497]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 22:41:01 spla-repro sudo[497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "volumio5onboarding"... Aug 25 22:41:01 spla-repro sudo[495]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:01 spla-repro sudo[497]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:01 spla-repro sudo[505]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:01 spla-repro sudo[505]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "alsa_controller"... Aug 25 22:41:01 spla-repro sudo[505]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:01 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "wizard"... Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "networkfs"... Aug 25 22:41:01 spla-repro volumio[454]: info: Starting Udev Watcher for removable devices Aug 25 22:41:01 spla-repro volumio[454]: info: Ignoring mount for partition: boot Aug 25 22:41:01 spla-repro volumio[454]: info: Ignoring mount for partition: volumio Aug 25 22:41:01 spla-repro volumio[454]: info: Ignoring mount for partition: volumio_data Aug 25 22:41:01 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "volumio_command_line_client"... Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "upnp"... Aug 25 22:41:01 spla-repro volumio[454]: info: [1787690461837] Starting Upmpd Daemon Aug 25 22:41:01 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "my_music"... Aug 25 22:41:01 spla-repro volumio[454]: info: Loading plugin "mpd"... Aug 25 22:41:02 spla-repro volumio-remote-updater[725]: [2026-08-25 22:41:02] [connect] Successful connection Aug 25 22:41:02 spla-repro volumio[454]: info: Loading plugin "upnp_browser"... Aug 25 22:41:02 spla-repro sudo[505]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:02 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 25 22:41:02 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:02 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:02 spla-repro go-librespot[536]: go-librespot daemon starting... Aug 25 22:41:02 spla-repro go-librespot[537]: time="2026-08-25T22:41:02+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:02 spla-repro go-librespot[537]: time="2026-08-25T22:41:02+02:00" level=debug msg="app state loaded" Aug 25 22:41:02 spla-repro go-librespot[537]: time="2026-08-25T22:41:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+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 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+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 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=info msg="zeroconf server listening on port 41375" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=debug msg="obtained new client token: AAHdjK+yG76IBPFAIpni/VVOazGXTSKQPDqAuUmj+PMSKE7F5MmXmy3Z+zEL5fHRVeY/rajugNG3YaqsJZa6FYTCETXUSbP3bYxmIMo7lubYnSw+qWkqLusnBfQ1hKjNEO+Sey37iypY/F1YlqiH6ORuGCaWxgiypMyLQpQQvOCh7X6gGE7R1C434nd9tpFzPg0/w6lHu77cCZrPMRPJV/ANeVFf8MO7XcPmlvP+bccQ5loSJbrBJes=" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=debug msg="completed challenge" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41:03+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:03 spla-repro go-librespot[537]: time="2026-08-25T22:41: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 25 22:41:03 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:03 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:03 spla-repro volumio[454]: info: Starting UPNP Browser Aug 25 22:41:03 spla-repro volumio[454]: info: Loading plugin "alarm-clock"... Aug 25 22:41:03 spla-repro volumio[454]: info: Loading plugin "airplay_emulation"... Aug 25 22:41:04 spla-repro volumio[454]: info: Starting Shairport Sync Aug 25 22:41:04 spla-repro volumio[454]: info: Loading plugin "last_100"... Aug 25 22:41:04 spla-repro volumio[454]: info: Loading plugin "webradio"... Aug 25 22:41:04 spla-repro volumio[454]: info: Loading plugin "i2s_dacs"... Aug 25 22:41:04 spla-repro volumio[454]: info: Loading plugin "volumiodiscovery"... Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** For more information see Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:41:04 spla-repro volumio[454]: *** WARNING *** For more information see Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** For more information see Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 22:41:04 spla-repro node[454]: *** WARNING *** For more information see Aug 25 22:41:04 spla-repro volumio[454]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 25 22:41:04 spla-repro volumio[454]: info: Discovery: Started advertising with name: Spálňa-repro Aug 25 22:41:04 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 22:41:04 spla-repro volumio[454]: info: Loading plugin "spop"... Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "outputs"... Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "albumart"... Aug 25 22:41:05 spla-repro volumio[454]: info: Plugin example_plugin is not enabled Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "inputs"... Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "updater_comm"... Aug 25 22:41:05 spla-repro volumio[454]: info: Plugin mpdemulation is not enabled Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "rest_api"... Aug 25 22:41:05 spla-repro volumio[454]: info: Loading plugin "websocket"... Aug 25 22:41:05 spla-repro volumio[454]: info: Starting Socket.io Server version 1.7.4 Aug 25 22:41:05 spla-repro volumio[454]: info: Plugin fusiondsp is not enabled Aug 25 22:41:05 spla-repro volumio[454]: info: Loading i18n strings for locale sk Aug 25 22:41:05 spla-repro volumio[454]: Updating browse sources language Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::initPlayerControls Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:41:05 spla-repro volumio[454]: Express server listening on port 3000 Aug 25 22:41:05 spla-repro volumio[454]: [Metrics] WebUI: 6s 703.98ms Aug 25 22:41:05 spla-repro volumio[454]: info: CoreStateMachine::resetVolumioState Aug 25 22:41:05 spla-repro volumio[454]: info: CoreStateMachine::getcurrentVolume Aug 25 22:41:05 spla-repro volumio[454]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:41:05 spla-repro volumio[454]: info: Cannot read play queue from file Aug 25 22:41:05 spla-repro volumio[454]: info: Volumio Network Manager: Network status updated: 1 Aug 25 22:41:05 spla-repro volumio[548]: Forking 3 albumart workers Aug 25 22:41:05 spla-repro volumio[454]: 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 25 22:41:05 spla-repro volumio[454]: Unable to parse: Aug 25 22:41:05 spla-repro volumio[454]: Simple mixer control 'Master',0 Aug 25 22:41:05 spla-repro volumio[454]: Capabilities: volume volume-joined Aug 25 22:41:05 spla-repro volumio[454]: Playback channels: Mono Aug 25 22:41:05 spla-repro volumio[454]: Capture channels: Mono Aug 25 22:41:05 spla-repro volumio[454]: Limits: 0 - 248 Aug 25 22:41:05 spla-repro volumio[454]: Mono: 112 [45%] Aug 25 22:41:05 spla-repro volumio[454]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:41:06 spla-repro volumio[454]: 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 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:06 spla-repro volumio[454]: 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: 2 Aug 25 22:41:06 spla-repro volumio[454]: Unable to parse: Aug 25 22:41:06 spla-repro volumio[454]: Simple mixer control 'Master',0 Aug 25 22:41:06 spla-repro volumio[454]: Capabilities: volume volume-joined Aug 25 22:41:06 spla-repro volumio[454]: Playback channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Capture channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Limits: 0 - 248 Aug 25 22:41:06 spla-repro volumio[454]: Mono: 112 [45%] Aug 25 22:41:06 spla-repro volumio[454]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::pushState Aug 25 22:41:06 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioPushState Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::updateTrackBlock Aug 25 22:41:06 spla-repro volumio[454]: info: CorePlayQueue::getTrackBlock Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::setRepeat null single undefined Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::pushState Aug 25 22:41:06 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioPushState Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::setRandom null Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::pushState Aug 25 22:41:06 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioPushState Aug 25 22:41:06 spla-repro volumio[454]: info: Setting Device type: Raspberry PI Aug 25 22:41:06 spla-repro volumio-remote-updater[725]: [2026-08-25 22:41:06] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787690462 101 Aug 25 22:41:06 spla-repro volumio[454]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Aug 25 22:41:06 spla-repro volumio[454]: info: Completed loading Core Plugins Aug 25 22:41:06 spla-repro volumio[454]: info: Preparing to generate the ALSA configuration file Aug 25 22:41:06 spla-repro volumio[454]: 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 25 22:41:06 spla-repro volumio[454]: Unable to parse: Aug 25 22:41:06 spla-repro volumio[454]: Simple mixer control 'Master',0 Aug 25 22:41:06 spla-repro volumio[454]: Capabilities: volume volume-joined Aug 25 22:41:06 spla-repro volumio[454]: Playback channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Capture channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Limits: 0 - 248 Aug 25 22:41:06 spla-repro volumio[454]: Mono: 112 [45%] Aug 25 22:41:06 spla-repro volumio[454]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 22:41:06 spla-repro volumio[454]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 22:41:06 spla-repro volumio[454]: info: Discovery: Found device kuchyna-repro Aug 25 22:41:06 spla-repro volumio[454]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 22:41:06 spla-repro volumio[454]: 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 25 22:41:06 spla-repro volumio[454]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 22:41:06 spla-repro volumio[454]: info: Discovery: Found device kupelna-repro Aug 25 22:41:06 spla-repro volumio[454]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 22:41:06 spla-repro volumio[454]: 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: 6 Aug 25 22:41:06 spla-repro volumio[454]: Unable to parse: Aug 25 22:41:06 spla-repro volumio[454]: Simple mixer control 'Master',0 Aug 25 22:41:06 spla-repro volumio[454]: Capabilities: volume volume-joined Aug 25 22:41:06 spla-repro volumio[454]: Playback channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Capture channels: Mono Aug 25 22:41:06 spla-repro volumio[454]: Limits: 0 - 248 Aug 25 22:41:06 spla-repro volumio[454]: Mono: 112 [45%] Aug 25 22:41:06 spla-repro volumio[454]: info: VolumeController:: Volume=undefined Mute =false Aug 25 22:41:06 spla-repro volumio[454]: info: CoreStateMachine::pushState Aug 25 22:41:06 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioPushState Aug 25 22:41:06 spla-repro volumio[454]: info: Asound.conf file unchanged, so no further update is needed Aug 25 22:41:06 spla-repro volumio[454]: info: Output device has changed, restarting MPD Aug 25 22:41:06 spla-repro volumio[454]: info: Output device has changed, restarting Shairport Sync Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:06 spla-repro sudo[607]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:06 spla-repro sudo[608]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:06 spla-repro sudo[607]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:41:06 spla-repro sudo[607]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:06 spla-repro sudo[607]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:06 spla-repro sudo[608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:41:06 spla-repro sudo[608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:06 spla-repro volumio[454]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:41:06 spla-repro volumio[454]: info: ___________ START PLUGINS ___________ Aug 25 22:41:06 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 25 22:41:06 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:06 spla-repro volumio[454]: info: ControllerMpd::onStart: Initializing MPD Aug 25 22:41:06 spla-repro volumio[454]: info: Creating MPD Configuration file Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:41:06 spla-repro volumio[454]: info: [1787690466798] CoreMusicLibrary::Adding element Mediálne servery Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:41:06 spla-repro sudo[620]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:06 spla-repro sudo[618]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:06 spla-repro sudo[620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 22:41:06 spla-repro go-librespot[617]: go-librespot daemon starting... Aug 25 22:41:06 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:06 spla-repro sudo[620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:06 spla-repro sudo[618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 22:41:06 spla-repro sudo[618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:06 spla-repro volumio[454]: info: UPNP Browser: Client initialized successfully Aug 25 22:41:06 spla-repro sudo[622]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:06 spla-repro sudo[620]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:06 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 22:41:06 spla-repro go-librespot[623]: time="2026-08-25T22:41:06+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:06 spla-repro go-librespot[623]: time="2026-08-25T22:41:06+02:00" level=debug msg="app state loaded" Aug 25 22:41:06 spla-repro sudo[622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 22:41:06 spla-repro sudo[622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:06 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:06 spla-repro go-librespot[623]: time="2026-08-25T22:41:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:06 spla-repro sudo[618]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:06 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:41:06 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:41:06 spla-repro systemd[1]: mpd.service: Consumed 4.766s CPU time. Aug 25 22:41:06 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:41:06 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:41:06 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:41:07 spla-repro volumio[454]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:07 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:41:07 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:41:07 spla-repro volumio[454]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:41:07 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 22:41:07 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 22:41:07 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 22:41:07 spla-repro volumio[454]: info: [1787690467135] CoreMusicLibrary::Adding element Last_100 Aug 25 22:41:07 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 22:41:07 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:41:07 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:41:07 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 22:41:07 spla-repro volumio[454]: info: [1787690467168] CoreMusicLibrary::Adding element Webradio Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:41:07 spla-repro volumio[454]: info: Initializing BBC Radios Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+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 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+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 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=info msg="zeroconf server listening on port 46465" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:07 spla-repro volumio[454]: info: Creating Spotify config file Aug 25 22:41:07 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:07 spla-repro sudo[648]: root : unable to resolve host spla-repro: System error Aug 25 22:41:07 spla-repro sudo[648]: sudo: unable to resolve host spla-repro: System error Aug 25 22:41:07 spla-repro sudo[648]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 22:41:07 spla-repro sudo[648]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 22:41:07 spla-repro sudo[648]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=debug msg="obtained new client token: AAHw5AqLaEN1cncxg2R0h4knQ9OUXVkz7OunAL1oJ2d+ubStJFjOFjCsRHmKNcXuqxhTJYgNxwHKclNRKPVSg+2u3E9pVn3S/GINVGno79jq082gE7AVTZP4vAHQp8cYUUsj7gR2TGLm/jESW6yEuVCz8LLUhjGtX1IX8Vkpcd+17/07aQqfkuB9FrsG+yuoNniDEwQJPzGoy5vjI+y4wULsV5vZDAwsUvMNE6unbiaZU6F/cPz623FXGw==" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=debug msg="completed challenge" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41:07+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:07 spla-repro go-librespot[623]: time="2026-08-25T22:41: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 25 22:41:07 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:07 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:07 spla-repro volumio[454]: info: Volumio Calling Home Aug 25 22:41:08 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:08 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:08 spla-repro volumio[564]: Starting albumart workers Aug 25 22:41:08 spla-repro volumio[565]: Starting albumart workers Aug 25 22:41:08 spla-repro volumio[454]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:41:08 spla-repro volumio[454]: info: Discovery: Found device Spálňa-repro Aug 25 22:41:08 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:08 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:08 spla-repro volumio[454]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 22:41:08 spla-repro volumio[563]: Starting albumart workers Aug 25 22:41:08 spla-repro volumio[454]: info: Discovery: Found device Spálňa-repro Aug 25 22:41:08 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:08 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:08 spla-repro volumio[454]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 22:41:08 spla-repro volumio[454]: info: MPD Permissions set Aug 25 22:41:08 spla-repro volumio[454]: info: MPD Permissions set Aug 25 22:41:08 spla-repro volumio[454]: info: Listing playlists Aug 25 22:41:08 spla-repro volumio[454]: info: Listing playlists Aug 25 22:41:08 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:41:08 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:08 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:09 spla-repro volumio[454]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 22:41:09 spla-repro volumio[454]: info: Volumio called home Aug 25 22:41:09 spla-repro volumio[454]: info: Spotify config file written Aug 25 22:41:09 spla-repro sudo[672]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:09 spla-repro sudo[672]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 22:41:09 spla-repro sudo[672]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:09 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:09 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:09 spla-repro go-librespot[674]: go-librespot daemon starting... Aug 25 22:41:09 spla-repro sudo[672]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+02:00" level=debug msg="app state loaded" Aug 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 22:41:09 spla-repro volumio[454]: info: No need to fix Spotify hosts Aug 25 22:41:09 spla-repro volumio[454]: 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: 6 Aug 25 22:41:09 spla-repro volumio[454]: 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: 6 Aug 25 22:41:09 spla-repro volumio[454]: info: Received Get System Info Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 22:41:09 spla-repro volumio[454]: info: Discovery: Getting this device information Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:09 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:09 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+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 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+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 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+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 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+02:00" level=info msg="zeroconf server listening on port 35245" Aug 25 22:41:09 spla-repro volumio[454]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 25 22:41:09 spla-repro go-librespot[675]: time="2026-08-25T22:41:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:10 spla-repro volumio[454]: info: New Spotify access tokenBQByQE66Qr... Aug 25 22:41:10 spla-repro volumio[454]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 22:41:10 spla-repro volumio[454]: info: Starting Shairport Sync Aug 25 22:41:10 spla-repro volumio[454]: info: Starting Shairport Sync Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=debug msg="obtained new client token: AAHz5XetANmiiPakF4BBaumSamJPg6EWv8+D8cBeV6VYLKB+du6moSyzki5ZUbeFXCXJnW4ZF5absc163Qhx0zImKYU8w/BzrDLlxFJIJBodV9ld7g0PIzvgY83vX3igC7fsPvNnFEhOjZogy82yg5Lrqldu48q8NXFZ30XoogQIv0Rtp3ZXsqbyIhaGadIR6ogRTdpcDV/3526vj/PcWvLTFagUb8hOoyjggDaTv3iwKtLJutSFzrw=" Aug 25 22:41:10 spla-repro volumio[454]: info: Starting Shairport Sync Aug 25 22:41:10 spla-repro sudo[702]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:10 spla-repro sudo[702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:41:10 spla-repro sudo[702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:10 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:10 spla-repro sudo[703]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:10 spla-repro sudo[706]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=debug msg="completed challenge" Aug 25 22:41:10 spla-repro sudo[703]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:41:10 spla-repro sudo[703]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:10 spla-repro sudo[706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 22:41:10 spla-repro sudo[706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:10 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:41:10 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:41:10 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:41:10 spla-repro systemd[1]: shairport-sync.service: Consumed 1.868s CPU time. Aug 25 22:41:10 spla-repro go-librespot[675]: time="2026-08-25T22:41:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:41:10 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:41:10 spla-repro sudo[702]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:10 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:10 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:10 spla-repro volumio[454]: info: Shairport-Sync Started Aug 25 22:41:10 spla-repro volumio[454]: Error adding Membership: Error: addMembership EINVAL Aug 25 22:41:10 spla-repro sudo[703]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:10 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:10 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 22:41:10 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 22:41:10 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:41:10 spla-repro volumio[454]: info: Shairport-Sync Started Aug 25 22:41:10 spla-repro volumio[454]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 22:41:10 spla-repro volumio[454]: info: Spotify Successfully logged in Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 22:41:10 spla-repro volumio[454]: info: [1787690470640] CoreMusicLibrary::Adding element Spotify Aug 25 22:41:10 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 22:41:10 spla-repro volumio[454]: Cannot find translation for source Spotify Aug 25 22:41:10 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 22:41:10 spla-repro sudo[706]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:10 spla-repro volumio[454]: info: Shairport-Sync Started Aug 25 22:41:11 spla-repro volumio5-onboarding[16326]: time=2026-08-25T22:41:11.114+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 25 22:41:11 spla-repro sudo[768]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:11 spla-repro sudo[767]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:11 spla-repro sudo[768]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 22:41:11 spla-repro sudo[767]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 22:41:11 spla-repro sudo[768]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:11 spla-repro sudo[767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:11 spla-repro sudo[768]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:11 spla-repro sudo[771]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:11 spla-repro sudo[771]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 22:41:11 spla-repro sudo[771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:11 spla-repro sudo[767]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:12 spla-repro sudo[771]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:12 spla-repro volumio[454]: info: Upmpdcli Daemon Started Aug 25 22:41:12 spla-repro mpd[667]: 2026-08-25T22:41:12 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 22:41:12 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 22:41:12 spla-repro sudo[622]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:12 spla-repro sudo[608]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:12 spla-repro volumio[454]: info: Completed starting Core Plugins Aug 25 22:41:12 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:41:12 spla-repro volumio[454]: info: ----- MyVolumio plugins startup ---- Aug 25 22:41:12 spla-repro volumio[454]: info: ------------------------------------------- Aug 25 22:41:12 spla-repro volumio[454]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 22:41:12 spla-repro volumio[454]: error: MPD error: The expression evaluated to a falsy value: Aug 25 22:41:12 spla-repro volumio[454]: assert.ok(self.idling) Aug 25 22:41:12 spla-repro volumio[454]: error: The expression evaluated to a falsy value: Aug 25 22:41:12 spla-repro volumio[454]: assert.ok(self.idling) Aug 25 22:41:12 spla-repro volumio[454]: info: MPD running with PID667 Aug 25 22:41:12 spla-repro volumio[454]: ,establishing connection Aug 25 22:41:12 spla-repro volumio[454]: error: updateQueue error: null Aug 25 22:41:12 spla-repro volumio[454]: error: updateQueue error: null Aug 25 22:41:12 spla-repro volumio[454]: info: go-librespot daemon successfully initialized Aug 25 22:41:13 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 22:41:13 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:13 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:13 spla-repro go-librespot[778]: go-librespot daemon starting... Aug 25 22:41:13 spla-repro go-librespot[779]: time="2026-08-25T22:41:13+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:13 spla-repro go-librespot[779]: time="2026-08-25T22:41:13+02:00" level=debug msg="app state loaded" Aug 25 22:41:13 spla-repro go-librespot[779]: time="2026-08-25T22:41:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=info msg="zeroconf server listening on port 37113" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="obtained new client token: AAEBoVC0lPURLzhN5Zbp1qFfHqIHA+pfPDE1ZSdFu0c1HOfTa1SYklbGWRjTsiFOr4lOTWk2VfhyuJwAX2OL9nIMPkBmITPwPZvO3om/aIA3PmDu7tEnjWLHEDQ3LI4jHKImwVa4iVAInLX4GI4KevB27VT679l4P2L2qjAbjaUA0OTP1L1EsEb8NTU1PM/SX8xbtmhY48eg5QiPIceAK8yG2o5hW9ezTCDEkarQQGorOtQLm7J838s=" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=debug msg="completed challenge" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:14 spla-repro go-librespot[779]: time="2026-08-25T22:41:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:41:14 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:14 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:15 spla-repro volumio[454]: info: Initializing connection to go-librespot Websocket Aug 25 22:41:15 spla-repro volumio[454]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:41:16 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:16 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:17 spla-repro volumio[454]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 22:41:17 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 22:41:17 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:17 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:17 spla-repro go-librespot[789]: go-librespot daemon starting... Aug 25 22:41:17 spla-repro go-librespot[790]: time="2026-08-25T22:41:17+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:17 spla-repro go-librespot[790]: time="2026-08-25T22:41:17+02:00" level=debug msg="app state loaded" Aug 25 22:41:17 spla-repro go-librespot[790]: time="2026-08-25T22:41:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+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 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+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 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=info msg="zeroconf server listening on port 45485" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=debug msg="obtained new client token: AAGszA+MqyqPgdtV1DytsA1ONPQSGYPuz9YCUjv2E+BZxbhJQzzNauTVW+hW+L1PtCDUdEZBkX2SbwPeLempjRKnm5hH9QNo1KooSRRKiDmSCf2hwIgL3NdnlLh2X6h26k7Ux1blzsO7ObumDU0YOziojjthjFcrq7cMCDM571ZNU2UBAaW8pez5JTlGtkwoWvAMFa3N6a0oy81KsHMhnor+yWrhW5df88DQ0ilfpNAKL68DzinfG6s=" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+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 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=debug msg="completed challenge" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:18 spla-repro go-librespot[790]: time="2026-08-25T22:41:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:41:18 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:18 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:18 spla-repro volumio[454]: info: Initializing connection to go-librespot Websocket Aug 25 22:41:18 spla-repro volumio[454]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 22:41:21 spla-repro volumio[454]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 22:41:21 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 25 22:41:21 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:21 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:21 spla-repro go-librespot[805]: go-librespot daemon starting... Aug 25 22:41:21 spla-repro go-librespot[806]: time="2026-08-25T22:41:21+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:21 spla-repro go-librespot[806]: time="2026-08-25T22:41:21+02:00" level=debug msg="app state loaded" Aug 25 22:41:21 spla-repro go-librespot[806]: time="2026-08-25T22:41:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=info msg="zeroconf server listening on port 33133" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:22 spla-repro volumio[454]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 22:41:22 spla-repro volumio[454]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 22:41:22 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:22 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:22 spla-repro volumio[454]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 22:41:22 spla-repro volumio[454]: info: MyVolumio login type: Token Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="obtained new client token: AAEsuzp59iBm3j+hP6xwlimKEYGtBhR40hHMHR9+UGlJtnaf+Cqayd1XKbQZG38PEL6+v8FtK1ipchYFaFcy52Zoz09wwir/k/w4fs5N6w/X2jyaLveoJt0LBDBtdd2+VbJlXp1F0gzI0OcMyFYhxoN7BslbPwtxQoJCtDhh1pX/cgQcpGoW0h+X79Ot8IQrIFu1cCoejyGwukAJhTslrGGBxphWhHDLAMBCDi4Qv4BwRrtzyKGLjiETIQ==" Aug 25 22:41:22 spla-repro volumio[454]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 22:41:22 spla-repro volumio[454]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=debug msg="completed challenge" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:22 spla-repro go-librespot[806]: time="2026-08-25T22:41:22+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 22:41:22 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:22 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:23 spla-repro volumio[454]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 22:41:23 spla-repro volumio[454]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 22:41:23 spla-repro volumio[454]: info: Streaming services startup Aug 25 22:41:23 spla-repro volumio[454]: info: Starting Streaming Daemon Aug 25 22:41:23 spla-repro sudo[831]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:23 spla-repro volumio[454]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 22:41:23 spla-repro sudo[831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 22:41:23 spla-repro sudo[831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:23 spla-repro sudo[831]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:23 spla-repro volumio[454]: info: Initializing connection to go-librespot Websocket Aug 25 22:41:23 spla-repro volumio[454]: error: Cannot start Volumio Streaming Daemon Aug 25 22:41:23 spla-repro volumio[454]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 22:41:23 spla-repro volumio[454]: sudo: unable to resolve host spla-repro: System error Aug 25 22:41:23 spla-repro volumio[454]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 22:41:23 spla-repro volumio[454]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:41:23 spla-repro volumio[454]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 25 22:41:24 spla-repro volumio[454]: info: MyVolumio token set successfully Aug 25 22:41:24 spla-repro volumio[454]: info: MYVOLUMIO: Adding device Aug 25 22:41:24 spla-repro volumio[454]: info: MYVOLUMIO: Evaluating Server Aug 25 22:41:24 spla-repro volumio[454]: info: MyVolumio status changed Aug 25 22:41:24 spla-repro volumio[454]: info: Streaming services startup Aug 25 22:41:24 spla-repro volumio[454]: info: Starting Streaming Daemon Aug 25 22:41:24 spla-repro volumio[454]: info: Removing browser output: myVolumio user plan is not superstar Aug 25 22:41:24 spla-repro volumio[454]: info: Removing audio output: Aug 25 22:41:24 spla-repro volumio[454]: info: Stoppping Tunnel 1 Aug 25 22:41:24 spla-repro sudo[858]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:24 spla-repro sudo[858]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 22:41:24 spla-repro sudo[858]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:24 spla-repro sudo[858]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:24 spla-repro sudo[862]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:24 spla-repro sudo[862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 25 22:41:24 spla-repro sudo[862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:24 spla-repro volumio[454]: error: Cannot start Volumio Streaming Daemon Aug 25 22:41:24 spla-repro volumio[454]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 22:41:24 spla-repro volumio[454]: sudo: unable to resolve host spla-repro: System error Aug 25 22:41:24 spla-repro volumio[454]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 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 25 22:41:24 spla-repro sudo[862]: pam_unix(sudo:session): session closed for user root Aug 25 22:41:24 spla-repro volumio[454]: info: Remote SSH Stopped Aug 25 22:41:24 spla-repro volumio[454]: info: Setting Geolocation for MyVolumio to eu6 Aug 25 22:41:24 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:24 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:24 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:25 spla-repro volumio[454]: info: Successfully Added MyVolumio device Aug 25 22:41:25 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 25 22:41:25 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:25 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:25 spla-repro go-librespot[867]: go-librespot daemon starting... Aug 25 22:41:25 spla-repro go-librespot[868]: time="2026-08-25T22:41:25+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:25 spla-repro go-librespot[868]: time="2026-08-25T22:41:25+02:00" level=debug msg="app state loaded" Aug 25 22:41:25 spla-repro go-librespot[868]: time="2026-08-25T22:41:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:25 spla-repro volumio[454]: info: Updating MyVolumio device info Aug 25 22:41:25 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:25 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:25 spla-repro volumio[454]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 22:41:26 spla-repro volumio[454]: info: CoreCommandRouter::volumioGetState Aug 25 22:41:26 spla-repro volumio[454]: info: CorePlayQueue::getTrack 0 Aug 25 22:41:26 spla-repro volumio[454]: info: Listing playlists Aug 25 22:41:26 spla-repro volumio[454]: info: Listing playlists Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+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 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+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 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=info msg="zeroconf server listening on port 45025" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="obtained new client token: AAEPDoBDOcO5eNi+xDhHrqkiHex6n+Gph0diq1MZbrn9tWCgtPvkn8SV9k9zT4NKNZ6S8xo4C6kgWO0BwyD8/YUGLRzJ9YqkqeneCDk3ezGRWhi4hre5m8bIplPHpFWxrfzfzBkNW7Z6z19hU/vqE0y21nnCqTs0U5m1tMjZT/IZdegmRQdGSv2JyKbVl3LvXYC6RKfZlTuGJoiGggMIrnn2fi2WybV2S/Ndb0aM5YhCJuAxWZyU9Lk=" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="completed challenge" Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:26 spla-repro volumio[454]: info: Initializing connection to go-librespot Websocket Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41:26+02:00" level=debug msg="new websocket client" Aug 25 22:41:26 spla-repro volumio[454]: info: Connection to go-librespot Websocket established Aug 25 22:41:26 spla-repro go-librespot[868]: time="2026-08-25T22:41: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 25 22:41:26 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:26 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 22:41:26 spla-repro volumio[454]: info: Connection to go-librespot Websocket closed Aug 25 22:41:26 spla-repro volumio[454]: info: Successfully Updated MyVolumio device Aug 25 22:41:29 spla-repro volumio[454]: info: Getting Spotify volume Aug 25 22:41:29 spla-repro volumio[454]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:41:29 spla-repro volumio[454]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 22:41:29 spla-repro volumio[454]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 22:41:29 spla-repro volumio[454]: errno: -111, Aug 25 22:41:29 spla-repro volumio[454]: code: 'ECONNREFUSED', Aug 25 22:41:29 spla-repro volumio[454]: syscall: 'connect', Aug 25 22:41:29 spla-repro volumio[454]: address: '127.0.0.1', Aug 25 22:41:29 spla-repro volumio[454]: port: 9879, Aug 25 22:41:29 spla-repro volumio[454]: response: undefined Aug 25 22:41:29 spla-repro volumio[454]: } Aug 25 22:41:29 spla-repro volumio[454]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 22:41:29 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 25 22:41:29 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:29 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 22:41:29 spla-repro go-librespot[890]: go-librespot daemon starting... Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=debug msg="app state loaded" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+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 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+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 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=info msg="zeroconf server listening on port 38115" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 22:41:29 spla-repro go-librespot[892]: time="2026-08-25T22:41:29+02:00" level=debug msg="obtained new client token: AAF2W54OB2m82qSqnpnMZra9ECLxGYjSbvBKGdhn28KZkGbmz4J5bMQjhjiifj8Z4dT60ycReQDbddhaf7cniDai6GZtj4Ot+zCg27ShODcEE4wHTvRmm+k8qcORiIWM0r5V8b3jd0g6ebEQWUB/TwpyjFKqskj/fvwQhedGMVjUUSgjI8ehDdt8RWaNGuwsXJOiJ2Wcb8OWXO6rF20IdRXnr/jX6CBzgxPUocJ1Jk3qGy3ByOtKfTqI9g==" Aug 25 22:41:30 spla-repro go-librespot[892]: time="2026-08-25T22:41:30+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 22:41:30 spla-repro go-librespot[892]: time="2026-08-25T22:41:30+02:00" level=debug msg="completed keyexchange" Aug 25 22:41:30 spla-repro go-librespot[892]: time="2026-08-25T22:41:30+02:00" level=debug msg="completed challenge" Aug 25 22:41:30 spla-repro go-librespot[892]: time="2026-08-25T22:41:30+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 22:41:30 spla-repro sudo[903]: volumio : unable to resolve host spla-repro: System error Aug 25 22:41:30 spla-repro sudo[903]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 22:40' Aug 25 22:41:30 spla-repro sudo[903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 22:41:30 spla-repro go-librespot[892]: time="2026-08-25T22:41: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 25 22:41:30 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 22:41:30 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"