Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:00 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:00 spla-repro volumio[6191]: info: Discovery: Connected to remote: 192.168.200.201 Aug 29 20:07:00 spla-repro volumio[6191]: info: MPD Permissions set Aug 29 20:07:00 spla-repro volumio[6191]: info: MPD Permissions set Aug 29 20:07:00 spla-repro volumio[6191]: info: Discovery: Connected to remote: 192.168.200.202 Aug 29 20:07:00 spla-repro volumio[6191]: info: Volumio called home Aug 29 20:07:00 spla-repro volumio[6191]: info: Spotify config file written Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:00 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:00 spla-repro sudo[6393]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:00 spla-repro sudo[6393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 20:07:00 spla-repro sudo[6393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:00 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 29 20:07:00 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 29 20:07:00 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:00 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:00 spla-repro go-librespot[6395]: go-librespot daemon starting... Aug 29 20:07:00 spla-repro sudo[6393]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:00 spla-repro go-librespot[6396]: time="2026-08-29T20:07:00+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:00 spla-repro go-librespot[6396]: time="2026-08-29T20:07:00+02:00" level=debug msg="app state loaded" Aug 29 20:07:00 spla-repro go-librespot[6396]: time="2026-08-29T20:07:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:00 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:01 spla-repro volumio[6191]: info: No need to fix Spotify hosts Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+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 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+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 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+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 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=info msg="zeroconf server listening on port 46561" Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:01 spla-repro volumio[6191]: info: Listing playlists Aug 29 20:07:01 spla-repro volumio[6191]: info: Listing playlists Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:01 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=debug msg="obtained new client token: AAGUVbvfKaxWVok3W/ydJeZfx+8GCNqPkjXjcGsV88QdoLT1Z6+VvoPzyDrSgVooPQUQ7PQnttswHkQRmuyXjJAClPRbBXM0dxp7U4LXbNWDiIovS0lla6IXm6qhzc9CA+SAd8z8vvkivaLXG2ZLKpnTLzsZ5gk+DTynuC4Dwj69Od1vJWNyLioiozlnaapvlblGFD7MhMNZ6b7X2U74pDHdC8e4vSXjmSjoui1m1LVN8gJbPFJ8OytCfg==" Aug 29 20:07:01 spla-repro volumio[6191]: 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 29 20:07:01 spla-repro volumio[6191]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:01 spla-repro volumio[6191]: info: Starting Shairport Sync Aug 29 20:07:01 spla-repro volumio[6191]: info: Starting Shairport Sync Aug 29 20:07:01 spla-repro volumio[6191]: info: Starting Shairport Sync Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=debug msg="completed challenge" Aug 29 20:07:01 spla-repro sudo[6434]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:01 spla-repro sudo[6438]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07:01+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:01 spla-repro sudo[6436]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:01 spla-repro sudo[6438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:01 spla-repro sudo[6434]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:01 spla-repro sudo[6438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:01 spla-repro sudo[6434]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:01 spla-repro sudo[6436]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:01 spla-repro sudo[6436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:01 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:01 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:01 spla-repro go-librespot[6396]: time="2026-08-29T20:07: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 29 20:07:01 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:01 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:01 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 20:07:01 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 20:07:01 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:07:01 spla-repro systemd[1]: shairport-sync.service: Consumed 1.964s CPU time. Aug 29 20:07:01 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:07:01 spla-repro sudo[6434]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:01 spla-repro sudo[6438]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:01 spla-repro sudo[6436]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:01 spla-repro volumio[6191]: info: Shairport-Sync Started Aug 29 20:07:01 spla-repro volumio[6191]: Error adding Membership: Error: addMembership EINVAL Aug 29 20:07:01 spla-repro volumio[6191]: info: Shairport-Sync Started Aug 29 20:07:01 spla-repro volumio[6191]: info: Shairport-Sync Started Aug 29 20:07:02 spla-repro sudo[6472]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:02 spla-repro sudo[6472]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 20:07:02 spla-repro sudo[6476]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:02 spla-repro sudo[6474]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:02 spla-repro sudo[6472]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:02 spla-repro sudo[6476]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 29 20:07:02 spla-repro sudo[6476]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:02 spla-repro sudo[6474]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 20:07:02 spla-repro sudo[6474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:02 spla-repro sudo[6472]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:02 spla-repro sudo[6474]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:02 spla-repro sudo[6476]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:02 spla-repro volumio[6191]: info: Upmpdcli Daemon Started Aug 29 20:07:03 spla-repro mpd[6377]: 2026-08-29T20:07:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 20:07:03 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 29 20:07:03 spla-repro sudo[6334]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:03 spla-repro sudo[6346]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:03 spla-repro volumio[6191]: info: Completed starting Core Plugins Aug 29 20:07:03 spla-repro volumio[6191]: info: ------------------------------------------- Aug 29 20:07:03 spla-repro volumio[6191]: info: ----- MyVolumio plugins startup ---- Aug 29 20:07:03 spla-repro volumio[6191]: info: ------------------------------------------- Aug 29 20:07:03 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 29 20:07:03 spla-repro volumio[6191]: error: MPD error: The expression evaluated to a falsy value: Aug 29 20:07:03 spla-repro volumio[6191]: assert.ok(self.idling) Aug 29 20:07:03 spla-repro volumio[6191]: error: The expression evaluated to a falsy value: Aug 29 20:07:03 spla-repro volumio[6191]: assert.ok(self.idling) Aug 29 20:07:03 spla-repro volumio[6191]: info: MPD running with PID6377 Aug 29 20:07:03 spla-repro volumio[6191]: ,establishing connection Aug 29 20:07:03 spla-repro volumio[6191]: error: updateQueue error: null Aug 29 20:07:03 spla-repro volumio[6191]: error: updateQueue error: null Aug 29 20:07:04 spla-repro volumio[6191]: info: go-librespot daemon successfully initialized Aug 29 20:07:04 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 29 20:07:04 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:05 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:05 spla-repro go-librespot[6484]: go-librespot daemon starting... Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=debug msg="app state loaded" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07: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 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07: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 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07: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 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=info msg="zeroconf server listening on port 40639" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=debug msg="obtained new client token: AAHCrJxHOWdwIagnomvyOvljweQz5BB/uB06gNianNrVEO0SVjXadC0+481oqc2YzB+MuvP7Fk0Wh0vVVlWLyIuySSe3vZR98MZDjdt6p9YiGwJWOSP+m8YmQdC2s8/JHHqcJua4E19ITgu/OaE0bY68/hlyasDn5o0Eq3OggSSEGBKqIkGRRPqTG2DxHVbVYDgyU7we3oQ5Wsl/jOZEM7R5/R7HTQLkOUn1yazaMq5FKKpIhvjl8gRsxw==" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=debug msg="completed challenge" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07:05+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:05 spla-repro go-librespot[6485]: time="2026-08-29T20:07: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 29 20:07:05 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:05 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:07 spla-repro volumio[6191]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:07 spla-repro volumio[6191]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:08 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:08 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:08 spla-repro volumio[6191]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 29 20:07:08 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 29 20:07:08 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:09 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:09 spla-repro go-librespot[6494]: go-librespot daemon starting... Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=debug msg="app state loaded" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07: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 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07: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 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07: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 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=info msg="zeroconf server listening on port 36719" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=debug msg="obtained new client token: AAHvCCcyG2XA+2onZW5/cHraGBwK6JJvYBMBTaz8wzarYj6hN1Olpxo89ruKytaSoO3dkfOGKfSEs5Sl8N4r0vhNvH2jVDyGfJPpdjGteKiNmj1ab5Yu+8eXVZJvQe+uvnrbnNFP12mvfpQa62KLFe5YVZKJP45tluEryYDJ4FhrbORHOHkGnCz5Cc1Pkamavsny75zOX0rgXvxhSzRT3mEdlPgun4NOyCg0Kh/8lbYVESfoPrh/5v7y+Q==" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+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 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=debug msg="completed challenge" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07:09+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:09 spla-repro go-librespot[6495]: time="2026-08-29T20:07: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 29 20:07:09 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:09 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:10 spla-repro volumio[6191]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:10 spla-repro volumio[6191]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin bluetooth to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin multiroom to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin metavolumio to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin cd_controller to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 29 20:07:12 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 29 20:07:12 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 29 20:07:12 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:13 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:13 spla-repro go-librespot[6518]: go-librespot daemon starting... Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=debug msg="app state loaded" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:13 spla-repro volumio[6191]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 29 20:07:13 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 29 20:07:13 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:13 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:13 spla-repro volumio[6191]: info: Starting MyVolumio Remote Streaming Endpoints Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07: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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+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 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+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 29 20:07:13 spla-repro volumio[6191]: info: MyVolumio login type: Token Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=info msg="zeroconf server listening on port 44919" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:13 spla-repro volumio[6191]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 29 20:07:13 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=debug msg="obtained new client token: AAEfXtGZcuqA2tkHFV/EtiXHMXzs8bxfDWiZW5Oo8+6QDrXZaQYoaHIK74HowPL8nBOfIdpKMarz28phkfEUARfSvt7JpDBeRvURYEWbhm6uzwhklKimBbrAKmpilURMo3WktzoKnvTQ+ZCYHdJwpgE4rN1MqbXU3dgjds+wR23fCds3/6Vg2rx43eF9MqzhNg/gpZmcALZWzJjiIxUKJ8MkINg9UEcA45QP02VSuhN9wuPIbu6/ip2WrQ==" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=debug msg="completed challenge" Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07:13+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:13 spla-repro systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 29 20:07:13 spla-repro systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 29 20:07:13 spla-repro systemd[1]: welcome.service: Deactivated successfully. Aug 29 20:07:13 spla-repro systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 29 20:07:13 spla-repro systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 29 20:07:13 spla-repro go-librespot[6519]: time="2026-08-29T20:07: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 29 20:07:13 spla-repro systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 29 20:07:13 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:13 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:13 spla-repro welcome[6547]: Resolved ip:[1] 192.168.200.203 Aug 29 20:07:14 spla-repro systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 29 20:07:14 spla-repro systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 29 20:07:14 spla-repro systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 29 20:07:14 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 29 20:07:14 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 29 20:07:14 spla-repro volumio[6191]: info: Streaming services startup Aug 29 20:07:14 spla-repro volumio[6191]: info: Starting Streaming Daemon Aug 29 20:07:14 spla-repro sudo[6569]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:14 spla-repro volumio[6191]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 29 20:07:14 spla-repro sudo[6569]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 29 20:07:14 spla-repro sudo[6569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:14 spla-repro sudo[6569]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:14 spla-repro volumio[6191]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:14 spla-repro volumio[6191]: info: Received Get System Info Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 20:07:14 spla-repro volumio[6191]: info: Discovery: Getting this device information Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:14 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 20:07:14 spla-repro volumio[6191]: error: Cannot start Volumio Streaming Daemon Aug 29 20:07:14 spla-repro volumio[6191]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 29 20:07:14 spla-repro volumio[6191]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:14 spla-repro volumio[6191]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 20:07:14 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 20:07:14 spla-repro volumio[6191]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:15 spla-repro systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 29 20:07:15 spla-repro systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 29 20:07:15 spla-repro systemd[1]: setdatetime-helper.service: Consumed 1.337s CPU time. Aug 29 20:07:15 spla-repro volumio[6191]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 29 20:07:15 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:15.870+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 29 20:07:16 spla-repro volumio[6191]: info: MyVolumio token set successfully Aug 29 20:07:16 spla-repro volumio[6191]: info: MYVOLUMIO: Adding device Aug 29 20:07:16 spla-repro volumio[6191]: info: MYVOLUMIO: Evaluating Server Aug 29 20:07:16 spla-repro volumio[6191]: info: MyVolumio status changed Aug 29 20:07:16 spla-repro volumio[6191]: info: Streaming services startup Aug 29 20:07:16 spla-repro volumio[6191]: info: Starting Streaming Daemon Aug 29 20:07:16 spla-repro volumio[6191]: info: Removing browser output: myVolumio user plan is not superstar Aug 29 20:07:16 spla-repro volumio[6191]: info: Removing audio output: Aug 29 20:07:16 spla-repro volumio[6191]: info: Stoppping Tunnel 1 Aug 29 20:07:16 spla-repro sudo[6605]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:16 spla-repro sudo[6605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 29 20:07:16 spla-repro sudo[6605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:16 spla-repro sudo[6605]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:16 spla-repro sudo[6608]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:16 spla-repro volumio[6191]: error: Cannot start Volumio Streaming Daemon Aug 29 20:07:16 spla-repro volumio[6191]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 29 20:07:16 spla-repro volumio[6191]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:16 spla-repro volumio[6191]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 29 20:07:16 spla-repro sudo[6608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 29 20:07:16 spla-repro sudo[6608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 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 29 20:07:16 spla-repro sudo[6608]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:16 spla-repro volumio[6191]: info: Remote SSH Stopped Aug 29 20:07:16 spla-repro volumio[6191]: info: Setting Geolocation for MyVolumio to eu6 Aug 29 20:07:16 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:16 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:16 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:16 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 29 20:07:16 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:17 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:17 spla-repro go-librespot[6611]: go-librespot daemon starting... Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=debug msg="app state loaded" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+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 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+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 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+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 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=info msg="zeroconf server listening on port 39555" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=debug msg="obtained new client token: AAFmndHIEukSEZx4NY02CCHjEj+M0mtckW+LYpwwMof4mMOa+vyhOMo3zeFzTimNqTZo5Q6HF8mylYRsXUSIK29QkhMzvTDMjgS8eebeKrdmbPi8ye3+4cfRpwPs+IOLTV2KmtZ86d4U3CzBbfu3Ap5rWTwOPhpZAguBmFLewVZ3esJgdOabckd9NvAtRR46NZrPtUMaiFlEp0pRpaAbNjukyBTPWIPf+lirXorqSusT2fp26Gp7txH6Qw==" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=debug msg="completed challenge" Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07:17+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:17 spla-repro volumio[6191]: info: Updating MyVolumio device info Aug 29 20:07:17 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:17 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:17 spla-repro volumio[6191]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:17 spla-repro volumio[6191]: info: Successfully Added MyVolumio device Aug 29 20:07:17 spla-repro go-librespot[6612]: time="2026-08-29T20:07: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 29 20:07:17 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:17 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:17 spla-repro volumio[6191]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:17 spla-repro volumio[6191]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:18 spla-repro volumio[6191]: info: Successfully Updated MyVolumio device Aug 29 20:07:18 spla-repro volumio[6191]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:18 spla-repro volumio[6191]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:18 spla-repro volumio[6191]: info: Listing playlists Aug 29 20:07:18 spla-repro volumio[6191]: info: Listing playlists Aug 29 20:07:20 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 29 20:07:20 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:20 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:20 spla-repro go-librespot[6621]: go-librespot daemon starting... Aug 29 20:07:20 spla-repro go-librespot[6622]: time="2026-08-29T20:07:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:20 spla-repro go-librespot[6622]: time="2026-08-29T20:07:20+02:00" level=debug msg="app state loaded" Aug 29 20:07:20 spla-repro go-librespot[6622]: time="2026-08-29T20:07:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:20 spla-repro volumio[6191]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:20 spla-repro go-librespot[6622]: time="2026-08-29T20:07:20+02:00" level=debug msg="new websocket client" Aug 29 20:07:20 spla-repro volumio[6191]: info: Connection to go-librespot Websocket established Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=info msg="zeroconf server listening on port 38859" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="obtained new client token: AAGynYsWPVnkvPBMe/8TF5p+oirdYNRJHppdDDtBYM4qWqaeFwM+QZs8t4flClUnR3YQTWv08qAR20QNem3tgUH+7nmzgwMGsk9oQ4HRUip5szTmMx2gA0Pwy+QqhPeGU7eB/aB8J8tY7EgCiacZfNDOU4aUD/iJuNJIjhPci6D4ZtLeiQdzlLjNZbgfhSioVXXjDRbltMMMwCAmDY7srKL3Wkuz7L+w4hvpgp9QWcGpOrr0RF72G/Y=" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=debug msg="completed challenge" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07:21+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:21 spla-repro go-librespot[6622]: time="2026-08-29T20:07: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 29 20:07:21 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:21 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:21 spla-repro volumio[6191]: info: Connection to go-librespot Websocket closed Aug 29 20:07:23 spla-repro volumio[6191]: info: Getting Spotify volume Aug 29 20:07:23 spla-repro volumio[6191]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:07:23 spla-repro volumio[6191]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:23 spla-repro volumio[6191]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 29 20:07:23 spla-repro volumio[6191]: errno: -111, Aug 29 20:07:23 spla-repro volumio[6191]: code: 'ECONNREFUSED', Aug 29 20:07:23 spla-repro volumio[6191]: syscall: 'connect', Aug 29 20:07:23 spla-repro volumio[6191]: address: '127.0.0.1', Aug 29 20:07:23 spla-repro volumio[6191]: port: 9879, Aug 29 20:07:23 spla-repro volumio[6191]: response: undefined Aug 29 20:07:23 spla-repro volumio[6191]: } Aug 29 20:07:23 spla-repro volumio[6191]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:07:24 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 29 20:07:24 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:24 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:24 spla-repro go-librespot[6661]: go-librespot daemon starting... Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+02:00" level=debug msg="app state loaded" Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:24 spla-repro sudo[6672]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:24 spla-repro sudo[6672]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 20:06' Aug 29 20:07:24 spla-repro sudo[6672]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07: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-gae2.spotify.com:80]" Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+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 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+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 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+02:00" level=info msg="zeroconf server listening on port 39963" Aug 29 20:07:24 spla-repro go-librespot[6662]: time="2026-08-29T20:07:24+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:24 spla-repro sudo[6672]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:25 spla-repro volumio[6191]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07:25+02:00" level=debug msg="obtained new client token: AAF6aRYaMwE6U+GJCem+qBSj166jcbGenbbbpAlfo+AvDOrqQr5VyxGfpWSdPqkIDQuArKqazC3gtQPqXEcKLPXJu77/dIP6Z4Uzz3EeBq1n85NMVegmzMEqDZ0qwYtZSKJyR/an+bBQiV3g/tiFGDYXl8c8H6QQd6qxIlrOx505B05SAKCnstx04qek7pEAIQYQHeeVjOtmoXq2q/c+wwDImFP7lxN6KnymtvoaNA0NEVgUTFi7VQ0=" Aug 29 20:07:25 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:25.062+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 29 20:07:25 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:25] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 29 20:07:25 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:25] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 29 20:07:25 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:25 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:25.071+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07:25+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:25 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 29 20:07:25 spla-repro systemd[1]: volumio.service: Consumed 32.638s CPU time. Aug 29 20:07:25 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07:25+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07:25+02:00" level=debug msg="completed challenge" Aug 29 20:07:25 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:25 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 12357. Aug 29 20:07:25 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 29 20:07:25 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 29 20:07:25 spla-repro systemd[1]: volumio.service: Consumed 32.638s CPU time. Aug 29 20:07:25 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 29 20:07:25 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 29 20:07:25 spla-repro go-librespot[6662]: time="2026-08-29T20:07: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 29 20:07:25 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:25 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:26 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:26.073+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 29 20:07:27 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:27 spla-repro volumio[6687]: info: ----- Volumio3 ---- Aug 29 20:07:27 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:27 spla-repro volumio[6687]: info: ----- System startup ---- Aug 29 20:07:27 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:28 spla-repro volumio[6687]: info: MYVOLUMIO Environment detected Aug 29 20:07:28 spla-repro volumio[6687]: info: Plugin folders cleanup Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning into folder /volumio/app/plugins/ Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category audio_interface Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category miscellanea Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category music_service Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category plugins.json Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category system_controller Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category user_interface Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning into folder /data/plugins/ Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category audio_interface Aug 29 20:07:28 spla-repro volumio[6687]: info: Scanning category music_service Aug 29 20:07:28 spla-repro volumio[6687]: info: Plugin folders cleanup completed Aug 29 20:07:28 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:28 spla-repro volumio[6687]: info: ----- Core plugins startup ---- Aug 29 20:07:28 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:28 spla-repro volumio[6687]: info: Loading plugins from folder /volumio/app/plugins/ Aug 29 20:07:28 spla-repro volumio[6687]: info: Adding plugin upnp to MyMusic Plugins Aug 29 20:07:28 spla-repro volumio[6687]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 29 20:07:28 spla-repro volumio[6687]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 29 20:07:28 spla-repro volumio[6687]: info: Loading plugins from folder /data/plugins/ Aug 29 20:07:28 spla-repro volumio[6687]: info: Loading plugin "system"... Aug 29 20:07:28 spla-repro volumio[6687]: info: Loading plugin "appearance"... Aug 29 20:07:28 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 29 20:07:28 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:28 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:28 spla-repro go-librespot[6714]: go-librespot daemon starting... Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+02:00" level=debug msg="app state loaded" Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+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 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+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 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+02:00" level=info msg="zeroconf server listening on port 33327" Aug 29 20:07:28 spla-repro go-librespot[6715]: time="2026-08-29T20:07:28+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07:29+02:00" level=debug msg="obtained new client token: AAHH9ohvjWVJFWXEep/bpA+hE0LT6W7+JqGk738rVyU+NzZzZWbiLexjgzLo5qtq/Tp7iwsBHnn24ZIes21gFK/6HUeHVedz03FkPwnud5uny3SGcvG9gI8YGhh/ApcNkWzA78sLGn49Hq3m4cbFh2c9gFzzR5CqxopjesynLoDSJ67NP+VlSB5NWrHbALDFeZjq3Cxkw/eTfO8Cn90uEqOjP7F9Z9hfskk8ubPsfPVm0dDYPq+kiHY=" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07:29+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07:29+02:00" level=debug msg="completed challenge" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:29 spla-repro go-librespot[6715]: time="2026-08-29T20:07: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 29 20:07:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:29 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "network"... Aug 29 20:07:29 spla-repro volumio[6687]: info: Refreshing Cached IP Addresses Aug 29 20:07:29 spla-repro sudo[6725]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:29 spla-repro sudo[6727]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:29 spla-repro sudo[6725]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 20:07:29 spla-repro sudo[6725]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "services"... Aug 29 20:07:29 spla-repro sudo[6727]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "volumio5onboarding"... Aug 29 20:07:29 spla-repro sudo[6727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:29 spla-repro sudo[6725]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:29 spla-repro sudo[6727]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:29 spla-repro sudo[6731]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "alsa_controller"... Aug 29 20:07:29 spla-repro sudo[6731]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 29 20:07:29 spla-repro sudo[6731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:29 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "wizard"... Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "networkfs"... Aug 29 20:07:29 spla-repro volumio[6687]: info: Starting Udev Watcher for removable devices Aug 29 20:07:29 spla-repro volumio[6687]: info: Ignoring mount for partition: boot Aug 29 20:07:29 spla-repro volumio[6687]: info: Ignoring mount for partition: volumio Aug 29 20:07:29 spla-repro volumio[6687]: info: Ignoring mount for partition: volumio_data Aug 29 20:07:29 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "volumio_command_line_client"... Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "upnp"... Aug 29 20:07:29 spla-repro volumio[6687]: info: [1788026849943] Starting Upmpd Daemon Aug 29 20:07:29 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "my_music"... Aug 29 20:07:29 spla-repro volumio[6687]: info: Loading plugin "mpd"... Aug 29 20:07:30 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:30] [connect] Successful connection Aug 29 20:07:30 spla-repro volumio[6687]: info: Loading plugin "upnp_browser"... Aug 29 20:07:30 spla-repro sudo[6731]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:32 spla-repro volumio[6687]: info: Starting UPNP Browser Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "alarm-clock"... Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "airplay_emulation"... Aug 29 20:07:32 spla-repro volumio[6687]: info: Starting Shairport Sync Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "last_100"... Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "webradio"... Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "i2s_dacs"... Aug 29 20:07:32 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 29 20:07:32 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "volumiodiscovery"... Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** For more information see Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:07:32 spla-repro volumio[6687]: *** WARNING *** For more information see Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** For more information see Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:07:32 spla-repro node[6687]: *** WARNING *** For more information see Aug 29 20:07:32 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:32 spla-repro volumio[6687]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 29 20:07:32 spla-repro go-librespot[6758]: go-librespot daemon starting... Aug 29 20:07:32 spla-repro volumio[6687]: info: Discovery: Started advertising with name: Spálňa-repro Aug 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07:32+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07:32+02:00" level=debug msg="app state loaded" Aug 29 20:07:32 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:07:32 spla-repro volumio[6687]: info: Loading plugin "spop"... Aug 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07: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 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07: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 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07: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 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07:32+02:00" level=info msg="zeroconf server listening on port 46705" Aug 29 20:07:32 spla-repro go-librespot[6759]: time="2026-08-29T20:07:32+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07:33+02:00" level=debug msg="obtained new client token: AAF447ZK6xakhFatoN4SprY2/49+3K2ORaSb+oWOhjS74YX7womThE2VK468mpzK91rlRP42ez4R3lTGP/zDRO0n/1OhA6c/KgLR17slzbujVDVD/BZoVOyFXLFcHKSC8zeF0A/OXen+838VbKaAeHXZJQmVMKBiPdF3j0E1kieQ1BurhO3pFEWHBOfPnnz62G0Mvq5ZsfdwszEXGi9pf0oF1gl+/0pfsEQX21rzS9W4+jTUJADobj8=" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07:33+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07:33+02:00" level=debug msg="completed challenge" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07:33+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:33 spla-repro go-librespot[6759]: time="2026-08-29T20:07: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 29 20:07:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:33 spla-repro volumio[6687]: info: Loading plugin "outputs"... Aug 29 20:07:33 spla-repro volumio[6687]: info: Loading plugin "albumart"... Aug 29 20:07:33 spla-repro volumio[6687]: info: Plugin example_plugin is not enabled Aug 29 20:07:33 spla-repro volumio[6687]: info: Loading plugin "inputs"... Aug 29 20:07:33 spla-repro volumio[6687]: info: Loading plugin "updater_comm"... Aug 29 20:07:34 spla-repro volumio[6687]: info: Plugin mpdemulation is not enabled Aug 29 20:07:34 spla-repro volumio[6687]: info: Loading plugin "rest_api"... Aug 29 20:07:34 spla-repro volumio[6687]: info: Loading plugin "websocket"... Aug 29 20:07:34 spla-repro volumio[6687]: info: Starting Socket.io Server version 1.7.4 Aug 29 20:07:34 spla-repro volumio[6687]: info: Plugin fusiondsp is not enabled Aug 29 20:07:34 spla-repro volumio[6687]: info: Loading i18n strings for locale sk Aug 29 20:07:34 spla-repro volumio[6687]: Updating browse sources language Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::initPlayerControls Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: Express server listening on port 3000 Aug 29 20:07:34 spla-repro volumio[6687]: [Metrics] WebUI: 7s 508.58ms Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::resetVolumioState Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::getcurrentVolume Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 20:07:34 spla-repro volumio[6687]: info: Cannot read play queue from file Aug 29 20:07:34 spla-repro volumio[6687]: info: Volumio Network Manager: Network status updated: 1 Aug 29 20:07:34 spla-repro volumio[6770]: Forking 3 albumart workers Aug 29 20:07:34 spla-repro volumio[6687]: 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 29 20:07:34 spla-repro volumio[6687]: Unable to parse: Aug 29 20:07:34 spla-repro volumio[6687]: Simple mixer control 'Master',0 Aug 29 20:07:34 spla-repro volumio[6687]: Capabilities: volume volume-joined Aug 29 20:07:34 spla-repro volumio[6687]: Playback channels: Mono Aug 29 20:07:34 spla-repro volumio[6687]: Capture channels: Mono Aug 29 20:07:34 spla-repro volumio[6687]: Limits: 0 - 248 Aug 29 20:07:34 spla-repro volumio[6687]: Mono: 112 [45%] Aug 29 20:07:34 spla-repro volumio[6687]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 29 20:07:34 spla-repro volumio[6687]: 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 29 20:07:34 spla-repro volumio[6687]: info: Received Get System Info Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 20:07:34 spla-repro volumio[6687]: info: Discovery: Getting this device information Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 20:07:34 spla-repro volumio[6687]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 20:07:34 spla-repro volumio[6687]: Unable to parse: Aug 29 20:07:34 spla-repro volumio[6687]: Simple mixer control 'Master',0 Aug 29 20:07:34 spla-repro volumio[6687]: Capabilities: volume volume-joined Aug 29 20:07:34 spla-repro volumio[6687]: Playback channels: Mono Aug 29 20:07:34 spla-repro volumio[6687]: Capture channels: Mono Aug 29 20:07:34 spla-repro volumio[6687]: Limits: 0 - 248 Aug 29 20:07:34 spla-repro volumio[6687]: Mono: 112 [45%] Aug 29 20:07:34 spla-repro volumio[6687]: info: VolumeController:: Volume=undefined Mute =false Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::pushState Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioPushState Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::updateTrackBlock Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrackBlock Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::setRepeat null single undefined Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::pushState Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioPushState Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::setRandom null Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreStateMachine::pushState Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioPushState Aug 29 20:07:34 spla-repro volumio[6687]: info: Setting Device type: Raspberry PI Aug 29 20:07:34 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:34 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:34 spla-repro volumio[6687]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 29 20:07:34 spla-repro volumio[6687]: info: Completed loading Core Plugins Aug 29 20:07:34 spla-repro volumio[6687]: info: Preparing to generate the ALSA configuration file Aug 29 20:07:35 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788026850 101 Aug 29 20:07:35 spla-repro volumio[6687]: 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: 4 Aug 29 20:07:35 spla-repro volumio[6687]: Unable to parse: Aug 29 20:07:35 spla-repro volumio[6687]: Simple mixer control 'Master',0 Aug 29 20:07:35 spla-repro volumio[6687]: Capabilities: volume volume-joined Aug 29 20:07:35 spla-repro volumio[6687]: Playback channels: Mono Aug 29 20:07:35 spla-repro volumio[6687]: Capture channels: Mono Aug 29 20:07:35 spla-repro volumio[6687]: Limits: 0 - 248 Aug 29 20:07:35 spla-repro volumio[6687]: Mono: 112 [45%] Aug 29 20:07:35 spla-repro volumio[6687]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 29 20:07:35 spla-repro volumio[6687]: info: Listing playlists Aug 29 20:07:35 spla-repro volumio[6687]: info: Listing playlists Aug 29 20:07:35 spla-repro volumio[6687]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 29 20:07:35 spla-repro volumio[6687]: info: Discovery: Found device kuchyna-repro Aug 29 20:07:35 spla-repro volumio[6687]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 29 20:07:35 spla-repro volumio[6687]: 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 29 20:07:35 spla-repro volumio[6687]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 29 20:07:35 spla-repro volumio[6687]: info: Discovery: Found device kupelna-repro Aug 29 20:07:35 spla-repro volumio[6687]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 29 20:07:35 spla-repro volumio[6687]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 29 20:07:35 spla-repro volumio[6687]: Unable to parse: Aug 29 20:07:35 spla-repro volumio[6687]: Simple mixer control 'Master',0 Aug 29 20:07:35 spla-repro volumio[6687]: Capabilities: volume volume-joined Aug 29 20:07:35 spla-repro volumio[6687]: Playback channels: Mono Aug 29 20:07:35 spla-repro volumio[6687]: Capture channels: Mono Aug 29 20:07:35 spla-repro volumio[6687]: Limits: 0 - 248 Aug 29 20:07:35 spla-repro volumio[6687]: Mono: 112 [45%] Aug 29 20:07:35 spla-repro volumio[6687]: info: VolumeController:: Volume=undefined Mute =false Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreStateMachine::pushState Aug 29 20:07:35 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::volumioPushState Aug 29 20:07:35 spla-repro volumio[6687]: info: Asound.conf file unchanged, so no further update is needed Aug 29 20:07:35 spla-repro volumio[6687]: info: Output device has changed, restarting MPD Aug 29 20:07:35 spla-repro volumio[6687]: info: Output device has changed, restarting Shairport Sync Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:35 spla-repro sudo[6826]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:35 spla-repro sudo[6826]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 20:07:35 spla-repro sudo[6826]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:35 spla-repro sudo[6826]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:35 spla-repro sudo[6828]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:35 spla-repro volumio[6687]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:07:35 spla-repro volumio[6687]: info: ___________ START PLUGINS ___________ Aug 29 20:07:35 spla-repro sudo[6828]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 20:07:35 spla-repro sudo[6828]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:35 spla-repro volumio[6687]: info: ControllerMpd::onStart: Initializing MPD Aug 29 20:07:35 spla-repro volumio[6687]: info: Creating MPD Configuration file Aug 29 20:07:35 spla-repro sudo[6836]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:07:35 spla-repro sudo[6838]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:35 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 29 20:07:35 spla-repro sudo[6836]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 29 20:07:35 spla-repro sudo[6836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:35 spla-repro volumio[6687]: info: [1788026855554] CoreMusicLibrary::Adding element Mediálne servery Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:07:35 spla-repro sudo[6838]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 20:07:35 spla-repro sudo[6840]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:35 spla-repro sudo[6838]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:35 spla-repro sudo[6840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 20:07:35 spla-repro sudo[6840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:35 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:35.650+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 29 20:07:35 spla-repro sudo[6838]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:35 spla-repro volumio[6687]: info: UPNP Browser: Client initialized successfully Aug 29 20:07:35 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 29 20:07:35 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 29 20:07:35 spla-repro systemd[1]: mpd.service: Consumed 5.392s CPU time. Aug 29 20:07:35 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 29 20:07:35 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 29 20:07:35 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:35 spla-repro volumio[6687]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:35 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 20:07:35 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 20:07:35 spla-repro volumio[6687]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:07:35 spla-repro sudo[6836]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:07:35 spla-repro volumio[6687]: info: [1788026855870] CoreMusicLibrary::Adding element Last_100 Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:07:35 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 29 20:07:35 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 29 20:07:35 spla-repro volumio[6687]: info: [1788026855887] CoreMusicLibrary::Adding element Webradio Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:07:35 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 29 20:07:35 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 29 20:07:35 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 29 20:07:35 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 20:07:35 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:07:35 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 20:07:35 spla-repro volumio[6687]: info: Initializing BBC Radios Aug 29 20:07:36 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:07:36 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:36 spla-repro volumio[6687]: info: Creating Spotify config file Aug 29 20:07:36 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:36 spla-repro sudo[6855]: root : unable to resolve host spla-repro: System error Aug 29 20:07:36 spla-repro sudo[6855]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:36 spla-repro sudo[6855]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 20:07:36 spla-repro sudo[6855]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 29 20:07:36 spla-repro sudo[6855]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:36 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 29 20:07:36 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:36 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:36 spla-repro go-librespot[6871]: go-librespot daemon starting... Aug 29 20:07:36 spla-repro go-librespot[6872]: time="2026-08-29T20:07:36+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:36 spla-repro volumio[6785]: Starting albumart workers Aug 29 20:07:37 spla-repro volumio[6687]: info: Volumio Calling Home Aug 29 20:07:37 spla-repro go-librespot[6872]: time="2026-08-29T20:07:37+02:00" level=info msg="zeroconf server listening on port 46527" Aug 29 20:07:37 spla-repro go-librespot[6872]: time="2026-08-29T20:07:37+02:00" level=info msg="using built-in mDNS responder" Aug 29 20:07:37 spla-repro volumio[6786]: Starting albumart workers Aug 29 20:07:37 spla-repro volumio[6788]: Starting albumart workers Aug 29 20:07:37 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 29 20:07:37 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:37 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:37 spla-repro volumio[6687]: info: Discovery: Connected to remote: 192.168.200.201 Aug 29 20:07:37 spla-repro volumio[6687]: info: MPD Permissions set Aug 29 20:07:37 spla-repro volumio[6687]: info: MPD Permissions set Aug 29 20:07:37 spla-repro volumio[6687]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 29 20:07:37 spla-repro volumio[6687]: info: Discovery: Found device Spálňa-repro Aug 29 20:07:37 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:37 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:38 spla-repro volumio[6687]: info: Discovery: Connected to remote: 192.168.200.202 Aug 29 20:07:38 spla-repro volumio[6687]: info: Volumio called home Aug 29 20:07:38 spla-repro volumio[6687]: info: Spotify config file written Aug 29 20:07:38 spla-repro sudo[6888]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:38 spla-repro sudo[6888]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 20:07:38 spla-repro sudo[6888]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:38 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 29 20:07:38 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 29 20:07:38 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:38 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:38 spla-repro go-librespot[6895]: go-librespot daemon starting... Aug 29 20:07:38 spla-repro sudo[6888]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:38 spla-repro go-librespot[6896]: time="2026-08-29T20:07:38+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:38 spla-repro go-librespot[6896]: time="2026-08-29T20:07:38+02:00" level=debug msg="app state loaded" Aug 29 20:07:38 spla-repro volumio[6687]: 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 29 20:07:38 spla-repro go-librespot[6896]: time="2026-08-29T20:07:38+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:07:38 spla-repro volumio[6687]: info: No need to fix Spotify hosts Aug 29 20:07:38 spla-repro volumio[6687]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 29 20:07:38 spla-repro volumio[6687]: info: Discovery: Found device Spálňa-repro Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:38 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 29 20:07:38 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:38 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+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 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+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 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=info msg="zeroconf server listening on port 41907" Aug 29 20:07:39 spla-repro volumio[6687]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:39 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:39 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:39 spla-repro volumio[6687]: info: Starting Shairport Sync Aug 29 20:07:39 spla-repro volumio[6687]: info: Starting Shairport Sync Aug 29 20:07:39 spla-repro volumio[6687]: info: Starting Shairport Sync Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=debug msg="obtained new client token: AAG7/L6AcxlgC4AH2KbjVXlWUzjE24p7MAX4o89r6Ix16PqYfXsYW9N6t32bPLDo0/bBe9XARn1bPEHrL/T+htMNC8ODd1ZjobzE9mzN7iE4motFAlSGfcdxwcWgTsQBtBhKYepVMT8aayx2jqNTRK6FIamSm7nbNYs4CFBZfC2jEPEdIqAd5MrYdlVkfpBGNH6eE0XBmUuSXJ2krOnZ/iDD6i/9johO+Y0bx3KoLc9z0fVEP63d1Pg=" Aug 29 20:07:39 spla-repro sudo[6929]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:39 spla-repro sudo[6929]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:39 spla-repro sudo[6929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:39 spla-repro sudo[6931]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:39 spla-repro sudo[6931]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:39 spla-repro sudo[6931]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:39 spla-repro sudo[6934]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:39 spla-repro sudo[6934]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:07:39 spla-repro sudo[6934]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:39 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:39 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:39 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=debug msg="completed challenge" Aug 29 20:07:39 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 20:07:39 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:07:39 spla-repro systemd[1]: shairport-sync.service: Consumed 1.934s CPU time. Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:39 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:07:39 spla-repro sudo[6934]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:39 spla-repro sudo[6931]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:39 spla-repro sudo[6929]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:39 spla-repro volumio[6687]: info: Shairport-Sync Started Aug 29 20:07:39 spla-repro volumio[6687]: Error adding Membership: Error: addMembership EINVAL Aug 29 20:07:39 spla-repro volumio[6687]: info: Shairport-Sync Started Aug 29 20:07:39 spla-repro volumio[6687]: info: Shairport-Sync Started Aug 29 20:07:39 spla-repro go-librespot[6896]: time="2026-08-29T20:07:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:07:39 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:39 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:39 spla-repro sudo[6967]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:39 spla-repro sudo[6967]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 20:07:40 spla-repro sudo[6967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:40 spla-repro sudo[6967]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:40 spla-repro sudo[6969]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:40 spla-repro sudo[6972]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:40 spla-repro sudo[6969]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 20:07:40 spla-repro sudo[6969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:40 spla-repro sudo[6972]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 29 20:07:40 spla-repro sudo[6972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:40 spla-repro sudo[6969]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:40 spla-repro sudo[6972]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:40 spla-repro volumio[6687]: info: Upmpdcli Daemon Started Aug 29 20:07:41 spla-repro mpd[6870]: 2026-08-29T20:07:41 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 20:07:41 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 29 20:07:41 spla-repro sudo[6828]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:41 spla-repro sudo[6840]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:41 spla-repro volumio[6687]: info: Completed starting Core Plugins Aug 29 20:07:41 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:41 spla-repro volumio[6687]: info: ----- MyVolumio plugins startup ---- Aug 29 20:07:41 spla-repro volumio[6687]: info: ------------------------------------------- Aug 29 20:07:41 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 29 20:07:41 spla-repro volumio[6687]: error: MPD error: The expression evaluated to a falsy value: Aug 29 20:07:41 spla-repro volumio[6687]: assert.ok(self.idling) Aug 29 20:07:41 spla-repro volumio[6687]: error: The expression evaluated to a falsy value: Aug 29 20:07:41 spla-repro volumio[6687]: assert.ok(self.idling) Aug 29 20:07:41 spla-repro volumio[6687]: info: go-librespot daemon successfully initialized Aug 29 20:07:41 spla-repro volumio[6687]: error: updateQueue error: null Aug 29 20:07:41 spla-repro volumio[6687]: info: MPD running with PID6870 Aug 29 20:07:41 spla-repro volumio[6687]: ,establishing connection Aug 29 20:07:41 spla-repro volumio[6687]: error: updateQueue error: null Aug 29 20:07:42 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 29 20:07:42 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:42 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:42 spla-repro go-librespot[6979]: go-librespot daemon starting... Aug 29 20:07:42 spla-repro go-librespot[6980]: time="2026-08-29T20:07:42+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:42 spla-repro go-librespot[6980]: time="2026-08-29T20:07:42+02:00" level=debug msg="app state loaded" Aug 29 20:07:42 spla-repro go-librespot[6980]: time="2026-08-29T20:07:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+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 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+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 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=info msg="zeroconf server listening on port 44189" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=debug msg="obtained new client token: AAFNF95sD7ADa9bkUCuf0/99pYWEs+6PBT6VD3ATJAcfRGYYeLGVp5DBC/agBtZMz1Y49HrC+bdSKPxNrUWyaMoB1MbSlc/scY5+zRmoEw+uBAz+fEh7T5uH3E4NzVgbsldO+DRqi2/1R9XRdH9Z67/OvtGbAoO/syvVkHxXxbIvlsZRwHghvrb7WKYznY8nzk5n7ChUkiBbEQVtgROKKGF/866NGFOTXP9sez2NUuwQsbVAvRrQomw=" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=debug msg="completed challenge" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:43 spla-repro go-librespot[6980]: time="2026-08-29T20:07:43+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:07:43 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:43 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:44 spla-repro volumio[6687]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:44 spla-repro volumio[6687]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:07:46 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 29 20:07:46 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:46 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:46 spla-repro go-librespot[6989]: go-librespot daemon starting... Aug 29 20:07:46 spla-repro go-librespot[6990]: time="2026-08-29T20:07:46+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:46 spla-repro go-librespot[6990]: time="2026-08-29T20:07:46+02:00" level=debug msg="app state loaded" Aug 29 20:07:46 spla-repro go-librespot[6990]: time="2026-08-29T20:07:46+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:46 spla-repro volumio[6687]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+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 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+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 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=info msg="zeroconf server listening on port 40399" Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=debug msg="obtained new client token: AAFelJEfl5DaMCar4ONcecBneY5m2x3Z4Q5dxcb1mypHxNBdmPivco1RVXshu8AwpMUDIArLZ46u6cVL9ccSr2Fyux+B23cF5ckgbRcEP6uONr32N8nZJOeIeR+iNoEztni0sfw1GMRXadwYyIxRCrs0UhdPA1QSxHNxiRhl0raiwfXnr2r9NphOxjRd41v1dH+PqmgIxAevvwEOYjZppZ6Cbn648vaxSf+RBYKd+QU8bH99BokaR3g=" Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+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 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 29 20:07:47 spla-repro volumio[6687]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:47 spla-repro go-librespot[6990]: time="2026-08-29T20:07:47+02:00" level=debug msg="new websocket client" Aug 29 20:07:47 spla-repro volumio[6687]: info: Connection to go-librespot Websocket established Aug 29 20:07:48 spla-repro volumio[6687]: info: CoreCommandRouter::volumioGetState Aug 29 20:07:48 spla-repro volumio[6687]: info: CorePlayQueue::getTrack 0 Aug 29 20:07:48 spla-repro go-librespot[6990]: time="2026-08-29T20:07:48+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:48 spla-repro go-librespot[6990]: time="2026-08-29T20:07:48+02:00" level=debug msg="completed challenge" Aug 29 20:07:48 spla-repro go-librespot[6990]: time="2026-08-29T20:07:48+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:48 spla-repro go-librespot[6990]: time="2026-08-29T20:07:48+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:07:48 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:48 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:48 spla-repro volumio[6687]: info: Connection to go-librespot Websocket closed Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin bluetooth to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin multiroom to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin metavolumio to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin cd_controller to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 29 20:07:50 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 29 20:07:51 spla-repro volumio[6687]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 29 20:07:51 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 29 20:07:51 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:51 spla-repro volumio[6687]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:07:51 spla-repro volumio[6687]: info: Starting MyVolumio Remote Streaming Endpoints Aug 29 20:07:51 spla-repro volumio[6687]: info: MyVolumio login type: Token Aug 29 20:07:51 spla-repro volumio[6687]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 29 20:07:51 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 29 20:07:51 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 29 20:07:51 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:51 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:51 spla-repro go-librespot[7013]: go-librespot daemon starting... Aug 29 20:07:51 spla-repro go-librespot[7014]: time="2026-08-29T20:07:51+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:51 spla-repro go-librespot[7014]: time="2026-08-29T20:07:51+02:00" level=debug msg="app state loaded" Aug 29 20:07:51 spla-repro go-librespot[7014]: time="2026-08-29T20:07:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+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 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+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 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+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 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=info msg="zeroconf server listening on port 45923" Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=debug msg="obtained new client token: AAEjpn3lUkXuHMR+1ek3GdfGHabfjO09lvlDoO6BG7kKt8fHwr3tqzAsSeq//0VfpHbT+xmkjGVGqFjh62+xVGgoA2k2FiNyu8iz3ryJWHYk8fLnLc5g6o6SNouFwyh8lS9q0korsvo2zsaUAEhbuS88/fBSq3NNE1lV5bgGnfiv8kwv2u+nQpuy73ZVqSDm7lKIP7+1rAbbHIPzF6k67t8D5ivpPpMMcHkZ8t9ur/OLxZV+yQCHegdI2Q==" Aug 29 20:07:52 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 29 20:07:52 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 29 20:07:52 spla-repro volumio[6687]: info: Streaming services startup Aug 29 20:07:52 spla-repro volumio[6687]: info: Starting Streaming Daemon Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:52 spla-repro sudo[7025]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:52 spla-repro volumio[6687]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 29 20:07:52 spla-repro sudo[7025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 29 20:07:52 spla-repro sudo[7025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=debug msg="completed challenge" Aug 29 20:07:52 spla-repro sudo[7025]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:52 spla-repro volumio[6687]: info: Getting Spotify volume Aug 29 20:07:52 spla-repro volumio[6687]: info: Initializing connection to go-librespot Websocket Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:52 spla-repro volumio[6687]: error: Cannot start Volumio Streaming Daemon Aug 29 20:07:52 spla-repro volumio[6687]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 29 20:07:52 spla-repro volumio[6687]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:52 spla-repro volumio[6687]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=debug msg="new websocket client" Aug 29 20:07:52 spla-repro volumio[6687]: 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 29 20:07:52 spla-repro volumio[6687]: info: Connection to go-librespot Websocket established Aug 29 20:07:52 spla-repro go-librespot[7014]: time="2026-08-29T20:07:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:07:52 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:52 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:52 spla-repro volumio[6687]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:07:52 spla-repro volumio[6687]: Error: socket hang up Aug 29 20:07:52 spla-repro volumio[6687]: at connResetException (node:internal/errors:720:14) Aug 29 20:07:52 spla-repro volumio[6687]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 29 20:07:52 spla-repro volumio[6687]: at Socket.emit (node:events:526:35) Aug 29 20:07:52 spla-repro volumio[6687]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 29 20:07:52 spla-repro volumio[6687]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 29 20:07:52 spla-repro volumio[6687]: code: 'ECONNRESET', Aug 29 20:07:52 spla-repro volumio[6687]: response: undefined Aug 29 20:07:52 spla-repro volumio[6687]: } Aug 29 20:07:52 spla-repro volumio[6687]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:07:53 spla-repro sudo[7045]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:53 spla-repro sudo[7045]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 20:06' Aug 29 20:07:53 spla-repro sudo[7045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:53 spla-repro sudo[7045]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:54 spla-repro volumio[6687]: sudo: unable to resolve host spla-repro: System error Aug 29 20:07:54 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:54.311+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 29 20:07:54 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:54.313+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 29 20:07:54 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:54] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 29 20:07:54 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:54] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 29 20:07:54 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:54 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 29 20:07:54 spla-repro systemd[1]: volumio.service: Consumed 32.009s CPU time. Aug 29 20:07:54 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 29 20:07:54 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 29 20:07:54 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 12358. Aug 29 20:07:54 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 29 20:07:54 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 29 20:07:54 spla-repro systemd[1]: volumio.service: Consumed 32.009s CPU time. Aug 29 20:07:54 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 29 20:07:54 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 29 20:07:55 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:07:55.314+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 29 20:07:55 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 29 20:07:55 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:55 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:55 spla-repro go-librespot[7078]: go-librespot daemon starting... Aug 29 20:07:55 spla-repro go-librespot[7079]: time="2026-08-29T20:07:55+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:55 spla-repro go-librespot[7079]: time="2026-08-29T20:07:55+02:00" level=debug msg="app state loaded" Aug 29 20:07:55 spla-repro go-librespot[7079]: time="2026-08-29T20:07:55+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+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 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+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 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+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 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=info msg="zeroconf server listening on port 36955" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=debug msg="obtained new client token: AAG5F1eKYFSFlYC1D7Kp+Gn1IztGJKxjWqFQ5M1ab/yJWgJDZLcaFnf9in8g7EPxuT814VF346XQKLJ2ZF9RnB75PrBZoXqb2+Ivgld0KI6p1A3wHRXIrYv3yRkvKlclTwMrh06HTWXtvSZrdIbfJbuB4MEhO0aZnCmTXwPEvtJd7tcS+TcpyTTu8NyO/6YO1Xsbw1Cmw5XUhqlunlmNOTRaF8bSjgCnlrJVGQ4ZeO2Jvyz2iseJ52iJ9w==" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=debug msg="completed keyexchange" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=debug msg="completed challenge" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:07:56 spla-repro go-librespot[7079]: time="2026-08-29T20:07:56+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:07:56 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:07:56 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:07:56 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:07:56 spla-repro volumio[7061]: info: ----- Volumio3 ---- Aug 29 20:07:56 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:07:56 spla-repro volumio[7061]: info: ----- System startup ---- Aug 29 20:07:56 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:07:57 spla-repro volumio[7061]: info: MYVOLUMIO Environment detected Aug 29 20:07:57 spla-repro volumio[7061]: info: Plugin folders cleanup Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning into folder /volumio/app/plugins/ Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category audio_interface Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category miscellanea Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category music_service Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category plugins.json Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category system_controller Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category user_interface Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning into folder /data/plugins/ Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category audio_interface Aug 29 20:07:57 spla-repro volumio[7061]: info: Scanning category music_service Aug 29 20:07:57 spla-repro volumio[7061]: info: Plugin folders cleanup completed Aug 29 20:07:57 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:07:57 spla-repro volumio[7061]: info: ----- Core plugins startup ---- Aug 29 20:07:57 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:07:57 spla-repro volumio[7061]: info: Loading plugins from folder /volumio/app/plugins/ Aug 29 20:07:57 spla-repro volumio[7061]: info: Adding plugin upnp to MyMusic Plugins Aug 29 20:07:57 spla-repro volumio[7061]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 29 20:07:57 spla-repro volumio[7061]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 29 20:07:57 spla-repro volumio[7061]: info: Loading plugins from folder /data/plugins/ Aug 29 20:07:57 spla-repro volumio[7061]: info: Loading plugin "system"... Aug 29 20:07:57 spla-repro volumio[7061]: info: Loading plugin "appearance"... Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "network"... Aug 29 20:07:59 spla-repro volumio[7061]: info: Refreshing Cached IP Addresses Aug 29 20:07:59 spla-repro sudo[7102]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:59 spla-repro sudo[7104]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:59 spla-repro sudo[7102]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "services"... Aug 29 20:07:59 spla-repro sudo[7104]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 20:07:59 spla-repro sudo[7104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:59 spla-repro sudo[7102]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "volumio5onboarding"... Aug 29 20:07:59 spla-repro sudo[7104]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:59 spla-repro sudo[7102]: pam_unix(sudo:session): session closed for user root Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "alsa_controller"... Aug 29 20:07:59 spla-repro sudo[7112]: volumio : unable to resolve host spla-repro: System error Aug 29 20:07:59 spla-repro sudo[7112]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 29 20:07:59 spla-repro sudo[7112]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:07:59 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "wizard"... Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "networkfs"... Aug 29 20:07:59 spla-repro volumio-remote-updater[725]: [2026-08-29 20:07:59] [connect] Successful connection Aug 29 20:07:59 spla-repro volumio[7061]: info: Starting Udev Watcher for removable devices Aug 29 20:07:59 spla-repro volumio[7061]: info: Ignoring mount for partition: boot Aug 29 20:07:59 spla-repro volumio[7061]: info: Ignoring mount for partition: volumio Aug 29 20:07:59 spla-repro volumio[7061]: info: Ignoring mount for partition: volumio_data Aug 29 20:07:59 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "volumio_command_line_client"... Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "upnp"... Aug 29 20:07:59 spla-repro volumio[7061]: info: [1788026879370] Starting Upmpd Daemon Aug 29 20:07:59 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "my_music"... Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "mpd"... Aug 29 20:07:59 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 29 20:07:59 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:59 spla-repro volumio[7061]: info: Loading plugin "upnp_browser"... Aug 29 20:07:59 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:07:59 spla-repro go-librespot[7135]: go-librespot daemon starting... Aug 29 20:07:59 spla-repro go-librespot[7136]: time="2026-08-29T20:07:59+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:07:59 spla-repro go-librespot[7136]: time="2026-08-29T20:07:59+02:00" level=debug msg="app state loaded" Aug 29 20:07:59 spla-repro go-librespot[7136]: time="2026-08-29T20:07:59+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:07:59 spla-repro sudo[7112]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08: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-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+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 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+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 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=info msg="zeroconf server listening on port 43191" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=debug msg="obtained new client token: AAFiL2QuMa1CNCE/p9f8CwvOGPMl/aPvRxpXar5F8wKvdt+G1H8FXHdk14PnLOSmzx+7A4U3Qh0tld0yCtlmg8V9OpHRUuustuORj4DTvUm/tOYM41nINLL8yOK1sZtrnY7nHRfv39fHy4YXH4y9qPBLTPunmLw4OEvU+lXbTDE7Oo09Z8KumQceGPAnl30rxkacXPDexppvqzwOnCMigI1AEk9HoN5pnr/x5i6y42Uh3odrVmcUMZe0uA==" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=debug msg="completed challenge" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:00 spla-repro go-librespot[7136]: time="2026-08-29T20:08:00+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:08:00 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:00 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:01 spla-repro volumio[7061]: info: Starting UPNP Browser Aug 29 20:08:01 spla-repro volumio[7061]: info: Loading plugin "alarm-clock"... Aug 29 20:08:01 spla-repro volumio[7061]: info: Loading plugin "airplay_emulation"... Aug 29 20:08:01 spla-repro volumio[7061]: info: Starting Shairport Sync Aug 29 20:08:01 spla-repro volumio[7061]: info: Loading plugin "last_100"... Aug 29 20:08:01 spla-repro volumio[7061]: info: Loading plugin "webradio"... Aug 29 20:08:02 spla-repro volumio[7061]: info: Loading plugin "i2s_dacs"... Aug 29 20:08:02 spla-repro volumio[7061]: info: Loading plugin "volumiodiscovery"... Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** For more information see Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:08:02 spla-repro volumio[7061]: *** WARNING *** For more information see Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** For more information see Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 29 20:08:02 spla-repro node[7061]: *** WARNING *** For more information see Aug 29 20:08:02 spla-repro volumio[7061]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 29 20:08:02 spla-repro volumio[7061]: info: Discovery: Started advertising with name: Spálňa-repro Aug 29 20:08:02 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 29 20:08:02 spla-repro volumio[7061]: info: Loading plugin "spop"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "outputs"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "albumart"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Plugin example_plugin is not enabled Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "inputs"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "updater_comm"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Plugin mpdemulation is not enabled Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "rest_api"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading plugin "websocket"... Aug 29 20:08:03 spla-repro volumio[7061]: info: Starting Socket.io Server version 1.7.4 Aug 29 20:08:03 spla-repro volumio[7061]: info: Plugin fusiondsp is not enabled Aug 29 20:08:03 spla-repro volumio[7061]: info: Loading i18n strings for locale sk Aug 29 20:08:03 spla-repro volumio[7061]: Updating browse sources language Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:08:03 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 29 20:08:03 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::initPlayerControls Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro go-librespot[7158]: go-librespot daemon starting... Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:08:03 spla-repro volumio[7061]: Express server listening on port 3000 Aug 29 20:08:03 spla-repro volumio[7061]: [Metrics] WebUI: 7s 669.97ms Aug 29 20:08:03 spla-repro go-librespot[7159]: time="2026-08-29T20:08:03+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:03 spla-repro go-librespot[7159]: time="2026-08-29T20:08:03+02:00" level=debug msg="app state loaded" Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreStateMachine::resetVolumioState Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreStateMachine::getcurrentVolume Aug 29 20:08:03 spla-repro volumio[7061]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 20:08:03 spla-repro go-librespot[7159]: time="2026-08-29T20:08:03+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:03 spla-repro volumio[7061]: info: Cannot read play queue from file Aug 29 20:08:03 spla-repro volumio[7061]: info: Volumio Network Manager: Network status updated: 1 Aug 29 20:08:03 spla-repro volumio[7061]: Unable to parse: Aug 29 20:08:03 spla-repro volumio[7061]: Simple mixer control 'Master',0 Aug 29 20:08:03 spla-repro volumio[7061]: Capabilities: volume volume-joined Aug 29 20:08:03 spla-repro volumio[7061]: Playback channels: Mono Aug 29 20:08:03 spla-repro volumio[7061]: Capture channels: Mono Aug 29 20:08:03 spla-repro volumio[7061]: Limits: 0 - 248 Aug 29 20:08:03 spla-repro volumio[7061]: Mono: 112 [45%] Aug 29 20:08:03 spla-repro volumio[7061]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 29 20:08:04 spla-repro volumio[7148]: Forking 3 albumart workers Aug 29 20:08:04 spla-repro volumio[7061]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=info msg="zeroconf server listening on port 45473" Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:04 spla-repro volumio[7061]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Aug 29 20:08:04 spla-repro volumio[7061]: Unable to parse: Aug 29 20:08:04 spla-repro volumio[7061]: Simple mixer control 'Master',0 Aug 29 20:08:04 spla-repro volumio[7061]: Capabilities: volume volume-joined Aug 29 20:08:04 spla-repro volumio[7061]: Playback channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Capture channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Limits: 0 - 248 Aug 29 20:08:04 spla-repro volumio[7061]: Mono: 112 [45%] Aug 29 20:08:04 spla-repro volumio[7061]: info: VolumeController:: Volume=undefined Mute =false Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::pushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioPushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::updateTrackBlock Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrackBlock Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioRetrievevolume Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="obtained new client token: AAEhn8cE0Sbz3Yl7elZx9CYr60gtUJydIWxvCxyV62DwaFz+leTey7t/ux/qF9cHZSvklayyhC9Wg8aNmIm95brxkT25FrAdlKYq7v8HGap22oeCyu++Wuxeh0XoNb53y9Fa2vXVY77+Sg5g+0G9fxPWsmkeiBnsEq68zPj3qzqrcYnF/xTs/Yz110OG6V1oPmjrSrFa+kbSYMiXw1TWs3fGdJA3MJynj9RfpVpOw6b2eFpkgb12iLxzIQ==" Aug 29 20:08:04 spla-repro volumio[7061]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::setRepeat null single undefined Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::pushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioPushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::setRandom null Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::pushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioPushState Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:04 spla-repro volumio[7061]: info: Setting Device type: Raspberry PI Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=debug msg="completed challenge" Aug 29 20:08:04 spla-repro volumio[7061]: info: Completed loading Core Plugins Aug 29 20:08:04 spla-repro volumio[7061]: info: Preparing to generate the ALSA configuration file Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:04 spla-repro volumio[7061]: Unable to parse: Aug 29 20:08:04 spla-repro volumio[7061]: Simple mixer control 'Master',0 Aug 29 20:08:04 spla-repro volumio[7061]: Capabilities: volume volume-joined Aug 29 20:08:04 spla-repro volumio[7061]: Playback channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Capture channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Limits: 0 - 248 Aug 29 20:08:04 spla-repro volumio[7061]: Mono: 112 [45%] Aug 29 20:08:04 spla-repro volumio[7061]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:04 spla-repro go-librespot[7159]: time="2026-08-29T20:08:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 29 20:08:04 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:04 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: Found device kuchyna-repro Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 29 20:08:04 spla-repro volumio[7061]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Aug 29 20:08:04 spla-repro volumio[7061]: Unable to parse: Aug 29 20:08:04 spla-repro volumio[7061]: Simple mixer control 'Master',0 Aug 29 20:08:04 spla-repro volumio[7061]: Capabilities: volume volume-joined Aug 29 20:08:04 spla-repro volumio[7061]: Playback channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Capture channels: Mono Aug 29 20:08:04 spla-repro volumio[7061]: Limits: 0 - 248 Aug 29 20:08:04 spla-repro volumio[7061]: Mono: 112 [45%] Aug 29 20:08:04 spla-repro volumio[7061]: info: VolumeController:: Volume=undefined Mute =false Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreStateMachine::pushState Aug 29 20:08:04 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:04 spla-repro volumio[7061]: info: CoreCommandRouter::volumioPushState Aug 29 20:08:04 spla-repro volumio[7061]: info: Listing playlists Aug 29 20:08:04 spla-repro volumio[7061]: info: Listing playlists Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: Found device kupelna-repro Aug 29 20:08:04 spla-repro volumio[7061]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 29 20:08:05 spla-repro volumio[7061]: 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 29 20:08:05 spla-repro volumio[7061]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Aug 29 20:08:05 spla-repro volumio[7061]: info: Asound.conf file unchanged, so no further update is needed Aug 29 20:08:05 spla-repro volumio[7061]: info: Output device has changed, restarting MPD Aug 29 20:08:05 spla-repro volumio[7061]: info: Output device has changed, restarting Shairport Sync Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:05 spla-repro sudo[7215]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:05 spla-repro sudo[7216]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:05 spla-repro sudo[7215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 20:08:05 spla-repro volumio[7061]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:08:05 spla-repro sudo[7215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:05 spla-repro sudo[7216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 20:08:05 spla-repro volumio[7061]: info: ___________ START PLUGINS ___________ Aug 29 20:08:05 spla-repro sudo[7216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:05 spla-repro sudo[7215]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:05 spla-repro volumio[7061]: info: ControllerMpd::onStart: Initializing MPD Aug 29 20:08:05 spla-repro volumio[7061]: info: Creating MPD Configuration file Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:08:05 spla-repro volumio[7061]: info: [1788026885298] CoreMusicLibrary::Adding element Mediálne servery Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:08:05 spla-repro sudo[7224]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:05 spla-repro sudo[7226]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:05 spla-repro sudo[7224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 29 20:08:05 spla-repro sudo[7224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:05 spla-repro sudo[7228]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:05 spla-repro sudo[7226]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 20:08:05 spla-repro sudo[7226]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:05 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 29 20:08:05 spla-repro volumio[7061]: info: UPNP Browser: Client initialized successfully Aug 29 20:08:05 spla-repro sudo[7226]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:05 spla-repro sudo[7228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 20:08:05 spla-repro sudo[7228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:05 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 29 20:08:05 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 29 20:08:05 spla-repro systemd[1]: mpd.service: Consumed 5.468s CPU time. Aug 29 20:08:05 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 29 20:08:05 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 29 20:08:05 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 29 20:08:05 spla-repro volumio[7061]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:05 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 20:08:05 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 20:08:05 spla-repro volumio[7061]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:08:05 spla-repro volumio[7061]: info: [1788026885640] CoreMusicLibrary::Adding element Last_100 Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:08:05 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 29 20:08:05 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 20:08:05 spla-repro volumio[7061]: info: [1788026885658] CoreMusicLibrary::Adding element Webradio Aug 29 20:08:05 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 20:08:05 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 29 20:08:05 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 29 20:08:05 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:08:05 spla-repro volumio[7061]: info: Initializing BBC Radios Aug 29 20:08:05 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 29 20:08:05 spla-repro sudo[7224]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:05 spla-repro volumio[7061]: info: Creating Spotify config file Aug 29 20:08:05 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:06 spla-repro sudo[7245]: root : unable to resolve host spla-repro: System error Aug 29 20:08:06 spla-repro sudo[7245]: sudo: unable to resolve host spla-repro: System error Aug 29 20:08:06 spla-repro sudo[7245]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 20:08:06 spla-repro sudo[7245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 29 20:08:06 spla-repro sudo[7245]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:06 spla-repro volumio[7175]: Starting albumart workers Aug 29 20:08:06 spla-repro volumio[7173]: Starting albumart workers Aug 29 20:08:06 spla-repro volumio[7174]: Starting albumart workers Aug 29 20:08:06 spla-repro volumio[7061]: info: Volumio Calling Home Aug 29 20:08:07 spla-repro volumio[7061]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Aug 29 20:08:07 spla-repro volumio[7061]: info: Received Get System Info Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: Getting this device information Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:07 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: Found device Spálňa-repro Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:07 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: Found device Spálňa-repro Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:07 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: Connected to remote: 192.168.200.201 Aug 29 20:08:07 spla-repro volumio[7061]: info: MPD Permissions set Aug 29 20:08:07 spla-repro volumio[7061]: info: MPD Permissions set Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 29 20:08:07 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:07 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:07 spla-repro volumio[7061]: info: Discovery: Connected to remote: 192.168.200.202 Aug 29 20:08:07 spla-repro volumio[7061]: info: Volumio called home Aug 29 20:08:07 spla-repro volumio[7061]: info: Spotify config file written Aug 29 20:08:07 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 29 20:08:07 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:08 spla-repro sudo[7271]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:08 spla-repro sudo[7271]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 20:08:08 spla-repro sudo[7271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:08 spla-repro go-librespot[7272]: go-librespot daemon starting... Aug 29 20:08:08 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:08 spla-repro go-librespot[7273]: time="2026-08-29T20:08:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:08 spla-repro go-librespot[7273]: time="2026-08-29T20:08:08+02:00" level=debug msg="app state loaded" Aug 29 20:08:08 spla-repro go-librespot[7273]: time="2026-08-29T20:08:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:08 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 29 20:08:08 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 29 20:08:08 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:08 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:08 spla-repro go-librespot[7288]: go-librespot daemon starting... Aug 29 20:08:08 spla-repro sudo[7271]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:08 spla-repro volumio5-onboarding[21614]: time=2026-08-29T20:08:08.413+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=debug msg="app state loaded" Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 20:08:08 spla-repro volumio[7061]: info: No need to fix Spotify hosts Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:08 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:08 spla-repro volumio[7061]: 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 29 20:08:08 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:08 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:08 spla-repro volumio[7061]: info: An error occurred while refreshing Spotify Token Error: Bad Request Aug 29 20:08:08 spla-repro volumio[7061]: info: Starting Shairport Sync Aug 29 20:08:08 spla-repro volumio[7061]: info: Starting Shairport Sync Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+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 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+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 29 20:08:08 spla-repro volumio[7061]: info: Starting Shairport Sync Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=info msg="zeroconf server listening on port 45429" Aug 29 20:08:08 spla-repro go-librespot[7289]: time="2026-08-29T20:08:08+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:08 spla-repro sudo[7315]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7315]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:08:09 spla-repro sudo[7315]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro sudo[7317]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7319]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:08:09 spla-repro sudo[7317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro sudo[7319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 20:08:09 spla-repro sudo[7319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:09 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08:09+02:00" level=debug msg="obtained new client token: AAHT6zpbkCjCiiRB7lIQ7EWnV1qmOYDYOVkm5aXmMvvKCXgQ07mVFWiGeRqOF/GFkzHl7HN5q6ePgRSl9c8xv/9xul11OhWH30ra8bFAnZ9Klfu7NQLnQy/aJUYPsQuZgUWoUC7IQ3kE5Pbq4PHmL/whDHzpV1YhBnZFvTIL6KPAKN3Vrq2xu5zjsEqqKBH0JcTFfwFuSbPb9db8702lWmjCQOJCBuOSiRIpPDdzybEbLf2oyerpzHk=" Aug 29 20:08:09 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 29 20:08:09 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 29 20:08:09 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:08:09 spla-repro systemd[1]: shairport-sync.service: Consumed 1.910s CPU time. Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:09 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 29 20:08:09 spla-repro sudo[7319]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro sudo[7315]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro sudo[7317]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08:09+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08:09+02:00" level=debug msg="completed challenge" Aug 29 20:08:09 spla-repro volumio[7061]: info: Shairport-Sync Started Aug 29 20:08:09 spla-repro volumio[7061]: Error adding Membership: Error: addMembership EINVAL Aug 29 20:08:09 spla-repro volumio[7061]: info: Shairport-Sync Started Aug 29 20:08:09 spla-repro volumio[7061]: info: Shairport-Sync Started Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08:09+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:09 spla-repro sudo[7339]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7339]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 29 20:08:09 spla-repro sudo[7339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro sudo[7339]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro sudo[7341]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7356]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:09 spla-repro sudo[7341]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 29 20:08:09 spla-repro sudo[7341]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro sudo[7356]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 29 20:08:09 spla-repro sudo[7356]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:09 spla-repro sudo[7341]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro sudo[7356]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:09 spla-repro volumio[7061]: info: Upmpdcli Daemon Started Aug 29 20:08:09 spla-repro go-librespot[7289]: time="2026-08-29T20:08: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 29 20:08:09 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:09 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:11 spla-repro mpd[7260]: 2026-08-29T20:08:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 20:08:11 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 29 20:08:11 spla-repro sudo[7216]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:11 spla-repro sudo[7228]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:11 spla-repro volumio[7061]: info: Completed starting Core Plugins Aug 29 20:08:11 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:08:11 spla-repro volumio[7061]: info: ----- MyVolumio plugins startup ---- Aug 29 20:08:11 spla-repro volumio[7061]: info: ------------------------------------------- Aug 29 20:08:11 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 29 20:08:11 spla-repro volumio[7061]: error: MPD error: The expression evaluated to a falsy value: Aug 29 20:08:11 spla-repro volumio[7061]: assert.ok(self.idling) Aug 29 20:08:11 spla-repro volumio[7061]: error: The expression evaluated to a falsy value: Aug 29 20:08:11 spla-repro volumio[7061]: assert.ok(self.idling) Aug 29 20:08:11 spla-repro volumio[7061]: error: updateQueue error: null Aug 29 20:08:11 spla-repro volumio[7061]: info: MPD running with PID7260 Aug 29 20:08:11 spla-repro volumio[7061]: ,establishing connection Aug 29 20:08:11 spla-repro volumio[7061]: error: updateQueue error: null Aug 29 20:08:11 spla-repro volumio[7061]: info: go-librespot daemon successfully initialized Aug 29 20:08:11 spla-repro volumio-remote-updater[725]: [2026-08-29 20:08:11] [connect] Successful connection Aug 29 20:08:11 spla-repro volumio-remote-updater[725]: [2026-08-29 20:08:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788026891 101 Aug 29 20:08:11 spla-repro volumio[7061]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 7 Aug 29 20:08:12 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 29 20:08:12 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:12 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:12 spla-repro go-librespot[7367]: go-librespot daemon starting... Aug 29 20:08:12 spla-repro go-librespot[7368]: time="2026-08-29T20:08:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:12 spla-repro go-librespot[7368]: time="2026-08-29T20:08:12+02:00" level=debug msg="app state loaded" Aug 29 20:08:12 spla-repro go-librespot[7368]: time="2026-08-29T20:08:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+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 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+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 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=info msg="zeroconf server listening on port 41113" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=debug msg="obtained new client token: AAHZN5HShYiHyNb6zW2ftcILvpTnQUYa0dtE7q9aSEa0zCmO2k2yP+L+WurWSgH303IR9gPTCH3VvAiLoa3hGOpk/edPfmmdat8eMOH6FOtvhKmtMKzvJhrIjo0MS5jTTUiLuH9TUgQ7fmq7KeB8ENosFCQWKtTXfrPBUgSTFJ9ZT58dZuusDXQkRvLgIijxK4s5mTU8T8XjbMGqrd4CZDgpRBJ3kHZL0gAGO3hojWLi4J7DRhliH6k=" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=debug msg="completed challenge" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08:13+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:13 spla-repro go-librespot[7368]: time="2026-08-29T20:08: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 29 20:08:13 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:13 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:14 spla-repro volumio[7061]: info: Initializing connection to go-librespot Websocket Aug 29 20:08:14 spla-repro volumio[7061]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:08:16 spla-repro volumio[7061]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 29 20:08:16 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 29 20:08:16 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:16 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:16 spla-repro go-librespot[7377]: go-librespot daemon starting... Aug 29 20:08:16 spla-repro go-librespot[7378]: time="2026-08-29T20:08:16+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:16 spla-repro go-librespot[7378]: time="2026-08-29T20:08:16+02:00" level=debug msg="app state loaded" Aug 29 20:08:16 spla-repro go-librespot[7378]: time="2026-08-29T20:08:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+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 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+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 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+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 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=info msg="zeroconf server listening on port 40721" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=debug msg="obtained new client token: AAFbt5ECwAhd8E12l8XQY5OkOFMMjV+El6Pww+vjSmCML8JlBtxSOI0iVu9iUEQct8F0uK2qvMH47aG8uMoTl45eXdyC9TxIuqS9yJ7ivjKpOrxIj+khCAS7ziWomJByhw+EHvCrXgssgySGS28pNDRsudkzq3N/fJHva3zRtyzgqjivfUq6x8pPfh9z2c/bti9kI8JI4u3dGO/eBL6V3+EqtrrGPOGtKsyfkpOuVoxXWbWtkcLCY+E=" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+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 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=debug msg="completed challenge" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08:17+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:17 spla-repro go-librespot[7378]: time="2026-08-29T20:08: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 29 20:08:17 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:17 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:17 spla-repro volumio[7061]: info: Initializing connection to go-librespot Websocket Aug 29 20:08:17 spla-repro volumio[7061]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:08:18 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:18 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin bluetooth to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin multiroom to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin metavolumio to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin cd_controller to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 29 20:08:19 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 29 20:08:20 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 29 20:08:20 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:20 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:20 spla-repro go-librespot[7402]: go-librespot daemon starting... Aug 29 20:08:20 spla-repro go-librespot[7403]: time="2026-08-29T20:08:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:20 spla-repro go-librespot[7403]: time="2026-08-29T20:08:20+02:00" level=debug msg="app state loaded" Aug 29 20:08:20 spla-repro go-librespot[7403]: time="2026-08-29T20:08:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:21 spla-repro volumio[7061]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 29 20:08:21 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 29 20:08:21 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:21 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:21 spla-repro volumio[7061]: info: Starting MyVolumio Remote Streaming Endpoints Aug 29 20:08:21 spla-repro volumio[7061]: info: MyVolumio login type: Token Aug 29 20:08:21 spla-repro volumio[7061]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 29 20:08:21 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+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 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+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 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=info msg="zeroconf server listening on port 34729" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=debug msg="obtained new client token: AAHc4/nozLVRzK9crrD/l7a9Twt6vfLIHn41o0agzvpNoXQWcIOzPMOpqr5dLmN1cJbxxcqe3JXTtFUXaDFChcCiYX5yQxG40ud22Vz/GYul3u6r8Rdv2Twb5mc42WLAIi0G8nV27gsYaqS/s6GAcPW/LSjJk3CuCjirsTiLsNXCYyInaSWa73HcSk0W2ENh4nOfM8c99hPKnetqWJTE1FcJZ7gmC8PDCRD0P/J5n4u+ddi/M7dlkXacSQ==" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=debug msg="completed challenge" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08:21+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:21 spla-repro go-librespot[7403]: time="2026-08-29T20:08: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 29 20:08:21 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:21 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:22 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 29 20:08:22 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 29 20:08:22 spla-repro volumio[7061]: info: Streaming services startup Aug 29 20:08:22 spla-repro volumio[7061]: info: Starting Streaming Daemon Aug 29 20:08:22 spla-repro sudo[7413]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:22 spla-repro volumio[7061]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 29 20:08:22 spla-repro sudo[7413]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 29 20:08:22 spla-repro sudo[7413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:22 spla-repro sudo[7413]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:22 spla-repro volumio[7061]: info: Initializing connection to go-librespot Websocket Aug 29 20:08:22 spla-repro volumio[7061]: error: Cannot start Volumio Streaming Daemon Aug 29 20:08:22 spla-repro volumio[7061]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 29 20:08:22 spla-repro volumio[7061]: sudo: unable to resolve host spla-repro: System error Aug 29 20:08:22 spla-repro volumio[7061]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 29 20:08:22 spla-repro volumio[7061]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:08:22 spla-repro volumio[7061]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 29 20:08:23 spla-repro volumio[7061]: info: MyVolumio token set successfully Aug 29 20:08:23 spla-repro volumio[7061]: info: MYVOLUMIO: Adding device Aug 29 20:08:23 spla-repro volumio[7061]: info: MYVOLUMIO: Evaluating Server Aug 29 20:08:23 spla-repro volumio[7061]: info: MyVolumio status changed Aug 29 20:08:23 spla-repro volumio[7061]: info: Streaming services startup Aug 29 20:08:23 spla-repro volumio[7061]: info: Starting Streaming Daemon Aug 29 20:08:23 spla-repro volumio[7061]: info: Removing browser output: myVolumio user plan is not superstar Aug 29 20:08:23 spla-repro volumio[7061]: info: Removing audio output: Aug 29 20:08:23 spla-repro volumio[7061]: info: Stoppping Tunnel 1 Aug 29 20:08:23 spla-repro sudo[7440]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:23 spla-repro sudo[7440]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 29 20:08:23 spla-repro sudo[7440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:23 spla-repro sudo[7440]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:23 spla-repro sudo[7443]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:23 spla-repro sudo[7443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 29 20:08:23 spla-repro volumio[7061]: error: Cannot start Volumio Streaming Daemon Aug 29 20:08:23 spla-repro volumio[7061]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 29 20:08:23 spla-repro volumio[7061]: sudo: unable to resolve host spla-repro: System error Aug 29 20:08:23 spla-repro volumio[7061]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 29 20:08:23 spla-repro sudo[7443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:23 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 29 20:08:23 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 29 20:08:23 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 29 20:08:23 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 29 20:08:23 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 29 20:08:23 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 29 20:08: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 29 20:08: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 29 20:08:24 spla-repro sudo[7443]: pam_unix(sudo:session): session closed for user root Aug 29 20:08:24 spla-repro volumio[7061]: info: Remote SSH Stopped Aug 29 20:08:24 spla-repro volumio[7061]: info: Setting Geolocation for MyVolumio to eu6 Aug 29 20:08:24 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:24 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:24 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:24 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 29 20:08:24 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:24 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:24 spla-repro go-librespot[7445]: go-librespot daemon starting... Aug 29 20:08:24 spla-repro go-librespot[7446]: time="2026-08-29T20:08:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:24 spla-repro go-librespot[7446]: time="2026-08-29T20:08:24+02:00" level=debug msg="app state loaded" Aug 29 20:08:24 spla-repro go-librespot[7446]: time="2026-08-29T20:08:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:25 spla-repro volumio[7061]: info: Updating MyVolumio device info Aug 29 20:08:25 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:25 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:25 spla-repro volumio[7061]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 20:08:25 spla-repro volumio[7061]: info: Successfully Added MyVolumio device Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+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 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+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 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=info msg="zeroconf server listening on port 39211" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="obtained new client token: AAF9rYw18A96kNGbp4RMqirbE8Ybn+A/XTcB6YHqeN+uwa5lSaZrx9Bq6mb8sxI7vrdrFCQr/mfSMwF6TFu7m+X0r9gPoiez0G6gRNHbzoaTMC10Zan9L/jNdPV/ngnpXDI9jhHWyDLop8isYJqcEzDA9UWHfCz+TYI5ct/n/926pOKeqjxUZKrARYDDZnMVP22ig1gb6y6hhxEQvRxvpsIu2uVVOYEWbo1wRi/O3GBPImqNIGX9C9w=" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="completed challenge" Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:25 spla-repro volumio[7061]: info: Successfully Updated MyVolumio device Aug 29 20:08:25 spla-repro volumio[7061]: info: Initializing connection to go-librespot Websocket Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08:25+02:00" level=debug msg="new websocket client" Aug 29 20:08:25 spla-repro volumio[7061]: info: Connection to go-librespot Websocket established Aug 29 20:08:25 spla-repro go-librespot[7446]: time="2026-08-29T20:08: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 29 20:08:25 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:25 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 29 20:08:25 spla-repro volumio[7061]: info: Connection to go-librespot Websocket closed Aug 29 20:08:28 spla-repro volumio[7061]: info: CoreCommandRouter::volumioGetState Aug 29 20:08:28 spla-repro volumio[7061]: info: CorePlayQueue::getTrack 0 Aug 29 20:08:28 spla-repro volumio[7061]: info: Listing playlists Aug 29 20:08:28 spla-repro volumio[7061]: info: Listing playlists Aug 29 20:08:28 spla-repro volumio[7061]: info: Getting Spotify volume Aug 29 20:08:28 spla-repro volumio[7061]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:08:28 spla-repro volumio[7061]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 20:08:28 spla-repro volumio[7061]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 29 20:08:28 spla-repro volumio[7061]: errno: -111, Aug 29 20:08:28 spla-repro volumio[7061]: code: 'ECONNREFUSED', Aug 29 20:08:28 spla-repro volumio[7061]: syscall: 'connect', Aug 29 20:08:28 spla-repro volumio[7061]: address: '127.0.0.1', Aug 29 20:08:28 spla-repro volumio[7061]: port: 9879, Aug 29 20:08:28 spla-repro volumio[7061]: response: undefined Aug 29 20:08:28 spla-repro volumio[7061]: } Aug 29 20:08:28 spla-repro volumio[7061]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 20:08:28 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 29 20:08:28 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:28 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 29 20:08:28 spla-repro go-librespot[7470]: go-librespot daemon starting... Aug 29 20:08:28 spla-repro go-librespot[7471]: time="2026-08-29T20:08:28+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 20:08:28 spla-repro go-librespot[7471]: time="2026-08-29T20:08:28+02:00" level=debug msg="app state loaded" Aug 29 20:08:28 spla-repro go-librespot[7471]: time="2026-08-29T20:08:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=info msg="zeroconf server listening on port 36443" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="obtained new client token: AAEzJ9Xp0y/66a+aDUTDz1WEA7G4BAQNf6xYWosGNH4q6ciEMOlsWyQe96govATOiiIbxV1iVm0RjxXwGqeLnreWhWvmKJANuFNnmATZhSkIicLovyLTXXsGNdI/uyopE/gFZtBW0++bwixYzh9mgUt+sw5xR7jH+m+4CoPsgeqKh65uES8kkKejhu9vRZH/M+jxifyxgcvOd4hLAb6QKal8ymFG6cZXbrDp0o43LMb5viAYofaapMo=" Aug 29 20:08:29 spla-repro sudo[7482]: volumio : unable to resolve host spla-repro: System error Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 29 20:08:29 spla-repro sudo[7482]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-29 20:07' Aug 29 20:08:29 spla-repro sudo[7482]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="completed keyexchange" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=debug msg="completed challenge" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 29 20:08:29 spla-repro go-librespot[7471]: time="2026-08-29T20:08: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 29 20:08:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 29 20:08:29 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"