Aug 25 14:14:00 spla-repro volumio[18627]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:00 spla-repro volumio[18627]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:01 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 25 14:14:01 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:01 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:01 spla-repro go-librespot[19037]: go-librespot daemon starting... Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="app state loaded" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14: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 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14: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 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14: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 25 14:14:01 spla-repro volumio[18627]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=info msg="zeroconf server listening on port 35581" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="new websocket client" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:01 spla-repro volumio[18627]: info: Connection to go-librespot Websocket established Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="obtained new client token: AAGJ614f3dwSqGSuZqeSWL4uz53e1HOFSaq/JKXSlSXjRLmVfz9XbkoWrhrkaCjnX1bPeGoeyg6vtB6Ld47Wptc+uYZ+upQW7p+NRinrhkXBkHDZ4r29GYiuXOfI3K5o2MJGZ1LfaErdS+t+W1gTtjbT3O2RmO2koFFoZYatHJsQdalNKGR3pcX0Wd3bRbSZZGho98k6KC9rpfN+TKYOXv17s/9zteNFDkUI/r4l40jp1sNULeKMQtJy6A==" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=debug msg="completed challenge" Aug 25 14:14:01 spla-repro go-librespot[19038]: time="2026-08-25T14:14:01+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:02 spla-repro go-librespot[19038]: time="2026-08-25T14:14:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:02 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:02 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:02 spla-repro volumio[18627]: info: Connection to go-librespot Websocket closed Aug 25 14:14:03 spla-repro volumio[18627]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 14:14:03 spla-repro volumio[18627]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 25 14:14:03 spla-repro volumio[18627]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:03 spla-repro volumio[18627]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:04 spla-repro volumio[18627]: info: Getting Spotify volume Aug 25 14:14:04 spla-repro volumio[18627]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:14:04 spla-repro volumio[18627]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:04 spla-repro volumio[18627]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 14:14:04 spla-repro volumio[18627]: errno: -111, Aug 25 14:14:04 spla-repro volumio[18627]: code: 'ECONNREFUSED', Aug 25 14:14:04 spla-repro volumio[18627]: syscall: 'connect', Aug 25 14:14:04 spla-repro volumio[18627]: address: '127.0.0.1', Aug 25 14:14:04 spla-repro volumio[18627]: port: 9879, Aug 25 14:14:04 spla-repro volumio[18627]: response: undefined Aug 25 14:14:04 spla-repro volumio[18627]: } Aug 25 14:14:04 spla-repro volumio[18627]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:14:05 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 14:14:05 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:05 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:05 spla-repro go-librespot[19060]: go-librespot daemon starting... Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="app state loaded" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:05 spla-repro sudo[19072]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:05 spla-repro sudo[19072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 14:13' Aug 25 14:14:05 spla-repro sudo[19072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:05 spla-repro sudo[19072]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=info msg="zeroconf server listening on port 46237" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:05 spla-repro volumio[18627]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:05 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:05.677+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 25 14:14:05 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:05.682+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:14:05 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 25 14:14:05 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 25 14:14:05 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:05 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 25 14:14:05 spla-repro systemd[1]: volumio.service: Consumed 29.033s CPU time. Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="obtained new client token: AAFu4yQXS0fYUONhmwyDwoIne7+HHXW6WPFwSC7qeGym2nBRa70okWq8MNTVrkPv/C6DWtkl/whr8oYlq62thdVRNcVAn+8ARjrQzFmosxDt92HhPcx0KjkrEttDmrL+Xd8+mcr/QKB7qlrF2UAQlygrh1jSiMclSzKSQy1FtZHkJlpmIBZciUcR3f5LiWDXWtOsWYgfseezyCm/aIYT+6VIXC7i1f68TNMgGoir0LN0dDpPX3gU9RgLDw==" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:05 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:14:05 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:14:05 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5436. Aug 25 14:14:05 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:14:05 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 25 14:14:05 spla-repro systemd[1]: volumio.service: Consumed 29.033s CPU time. Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=debug msg="completed challenge" Aug 25 14:14:05 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 25 14:14:05 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:14:05 spla-repro go-librespot[19061]: time="2026-08-25T14:14:05+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:06 spla-repro go-librespot[19061]: time="2026-08-25T14:14:06+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:06 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:06 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:06 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:06.683+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:14:07 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:07 spla-repro volumio[19088]: info: ----- Volumio3 ---- Aug 25 14:14:07 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:07 spla-repro volumio[19088]: info: ----- System startup ---- Aug 25 14:14:07 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:08 spla-repro volumio[19088]: info: MYVOLUMIO Environment detected Aug 25 14:14:08 spla-repro volumio[19088]: info: Plugin folders cleanup Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning into folder /volumio/app/plugins/ Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category audio_interface Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category miscellanea Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category music_service Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category plugins.json Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category system_controller Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category user_interface Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning into folder /data/plugins/ Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category audio_interface Aug 25 14:14:08 spla-repro volumio[19088]: info: Scanning category music_service Aug 25 14:14:08 spla-repro volumio[19088]: info: Plugin folders cleanup completed Aug 25 14:14:08 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:08 spla-repro volumio[19088]: info: ----- Core plugins startup ---- Aug 25 14:14:08 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:08 spla-repro volumio[19088]: info: Loading plugins from folder /volumio/app/plugins/ Aug 25 14:14:08 spla-repro volumio[19088]: info: Adding plugin upnp to MyMusic Plugins Aug 25 14:14:08 spla-repro volumio[19088]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 25 14:14:08 spla-repro volumio[19088]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 25 14:14:08 spla-repro volumio[19088]: info: Loading plugins from folder /data/plugins/ Aug 25 14:14:08 spla-repro volumio[19088]: info: Loading plugin "system"... Aug 25 14:14:08 spla-repro volumio[19088]: info: Loading plugin "appearance"... Aug 25 14:14:09 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 14:14:09 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:09 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:09 spla-repro go-librespot[19115]: go-librespot daemon starting... Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="app state loaded" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=info msg="zeroconf server listening on port 33737" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="obtained new client token: AAFk5DCTDnPVjPIW1rTr0orfjjQ11EhAfxIiHN3k7pC3NmsuwfPbvt5YPyjQY6JlTvn2geU1YUWeeaKAJk4ao6vs2gwfu3ujBnX/7rL5YyNJKsBH3/q+rcdgww30BSPR4efJVqHHl41CN7DI9JnbSEV5rT8bY8+Zqcez7+JCVE5Wz4ksWAxIdunSO6Q7hIE1p4T0DiOX3FN7+amSAqrBHYMUhjSS++S8RnZ0YJEv86qFbb1m1/1vnphnHg==" Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "network"... Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:09 spla-repro volumio[19088]: info: Refreshing Cached IP Addresses Aug 25 14:14:09 spla-repro sudo[19126]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:09 spla-repro sudo[19128]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:09 spla-repro sudo[19128]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "services"... Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=debug msg="completed challenge" Aug 25 14:14:09 spla-repro sudo[19128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:09 spla-repro sudo[19126]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:14:09 spla-repro sudo[19126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "volumio5onboarding"... Aug 25 14:14:09 spla-repro sudo[19128]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:09 spla-repro sudo[19135]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:09 spla-repro sudo[19126]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:09 spla-repro sudo[19135]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 25 14:14:09 spla-repro sudo[19135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "alsa_controller"... Aug 25 14:14:09 spla-repro go-librespot[19116]: time="2026-08-25T14:14:09+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:09 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "wizard"... Aug 25 14:14:09 spla-repro volumio[19088]: info: Loading plugin "networkfs"... Aug 25 14:14:10 spla-repro volumio[19088]: info: Starting Udev Watcher for removable devices Aug 25 14:14:10 spla-repro go-librespot[19116]: time="2026-08-25T14:14:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:10 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:10 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:10 spla-repro volumio[19088]: info: Ignoring mount for partition: boot Aug 25 14:14:10 spla-repro volumio[19088]: info: Ignoring mount for partition: volumio Aug 25 14:14:10 spla-repro volumio[19088]: info: Ignoring mount for partition: volumio_data Aug 25 14:14:10 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:10 spla-repro volumio[19088]: info: Loading plugin "volumio_command_line_client"... Aug 25 14:14:10 spla-repro volumio[19088]: info: Loading plugin "upnp"... Aug 25 14:14:10 spla-repro volumio[19088]: info: [1787660050061] Starting Upmpd Daemon Aug 25 14:14:10 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:10 spla-repro volumio[19088]: info: Loading plugin "my_music"... Aug 25 14:14:10 spla-repro volumio[19088]: info: Loading plugin "mpd"... Aug 25 14:14:10 spla-repro volumio[19088]: info: Loading plugin "upnp_browser"... Aug 25 14:14:10 spla-repro sudo[19135]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:10 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:10] [connect] Successful connection Aug 25 14:14:11 spla-repro systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 25 14:14:11 spla-repro systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Aug 25 14:14:11 spla-repro systemd[1]: welcome.service: Deactivated successfully. Aug 25 14:14:11 spla-repro systemd[1]: Stopped welcome.service - Show a welcome message on console. Aug 25 14:14:11 spla-repro systemd[1]: Stopping welcome.service - Show a welcome message on console... Aug 25 14:14:11 spla-repro systemd[1]: Starting welcome.service - Show a welcome message on console... Aug 25 14:14:11 spla-repro welcome[19176]: Resolved ip:[1] 192.168.200.203 Aug 25 14:14:11 spla-repro systemd[1]: Finished welcome.service - Show a welcome message on console. Aug 25 14:14:11 spla-repro systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Aug 25 14:14:11 spla-repro volumio[19088]: info: Starting UPNP Browser Aug 25 14:14:11 spla-repro volumio[19088]: info: Loading plugin "alarm-clock"... Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "airplay_emulation"... Aug 25 14:14:12 spla-repro volumio[19088]: info: Starting Shairport Sync Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "last_100"... Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "webradio"... Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "i2s_dacs"... Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "volumiodiscovery"... Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** For more information see Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:12 spla-repro volumio[19088]: *** WARNING *** For more information see Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** For more information see Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:12 spla-repro node[19088]: *** WARNING *** For more information see Aug 25 14:14:12 spla-repro volumio[19088]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 25 14:14:12 spla-repro volumio[19088]: info: Discovery: Started advertising with name: Spálňa-repro Aug 25 14:14:12 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:12 spla-repro volumio[19088]: info: Loading plugin "spop"... Aug 25 14:14:13 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 25 14:14:13 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:13 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:13 spla-repro go-librespot[19184]: go-librespot daemon starting... Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="app state loaded" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "outputs"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "albumart"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Plugin example_plugin is not enabled Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "inputs"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "updater_comm"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Plugin mpdemulation is not enabled Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "rest_api"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading plugin "websocket"... Aug 25 14:14:13 spla-repro volumio[19088]: info: Starting Socket.io Server version 1.7.4 Aug 25 14:14:13 spla-repro volumio[19088]: info: Plugin fusiondsp is not enabled Aug 25 14:14:13 spla-repro volumio[19088]: info: Loading i18n strings for locale sk Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:13 spla-repro volumio[19088]: Updating browse sources language Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=info msg="zeroconf server listening on port 33217" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="obtained new client token: AAFqKfQWFCLjrvoG26U6TmGIoMDhEQ8vwFMMEqv92lVWWVF3EyF2GpmUeqNlURHMYSQWFeIU29tDnLSOXB8G61pZjLi7sB73Jfq4JtdVfdpaHXX53aGa5co2/vwoGwoo2UTJiS0e9RY41kJzznsNR+j/ZCEqZmkNagfZSglohlr7vCJuBjsdgrEZnSY7Zh9UQdasP0oc7E3GPzSizWQCGOHyp92BcxNmc+e0868sdl7nM8QTPPL9HjBh1Q==" Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::initPlayerControls Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:13 spla-repro volumio[19088]: Express server listening on port 3000 Aug 25 14:14:13 spla-repro volumio[19088]: [Metrics] WebUI: 6s 617.12ms Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=debug msg="completed challenge" Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreStateMachine::resetVolumioState Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreStateMachine::getcurrentVolume Aug 25 14:14:13 spla-repro volumio[19088]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:14:13 spla-repro volumio[19088]: info: Cannot read play queue from file Aug 25 14:14:13 spla-repro volumio[19088]: info: Volumio Network Manager: Network status updated: 1 Aug 25 14:14:13 spla-repro go-librespot[19185]: time="2026-08-25T14:14:13+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:14 spla-repro volumio[19088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 25 14:14:14 spla-repro volumio[19088]: Unable to parse: Aug 25 14:14:14 spla-repro volumio[19088]: Simple mixer control 'Master',0 Aug 25 14:14:14 spla-repro volumio[19088]: Capabilities: volume volume-joined Aug 25 14:14:14 spla-repro volumio[19088]: Playback channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Capture channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Limits: 0 - 248 Aug 25 14:14:14 spla-repro volumio[19088]: Mono: 112 [45%] Aug 25 14:14:14 spla-repro volumio[19088]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:14:14 spla-repro go-librespot[19185]: time="2026-08-25T14:14:14+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:14 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:14 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:14 spla-repro volumio[19088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 25 14:14:14 spla-repro volumio[19193]: Forking 3 albumart workers Aug 25 14:14:14 spla-repro volumio[19088]: info: Received Get System Info Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Getting this device information Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 14:14:14 spla-repro volumio[19088]: info: Received Get System Info Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Getting this device information Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 14:14:14 spla-repro volumio[19088]: 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 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 14:14:14 spla-repro volumio[19088]: 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 25 14:14:14 spla-repro volumio[19088]: Unable to parse: Aug 25 14:14:14 spla-repro volumio[19088]: Simple mixer control 'Master',0 Aug 25 14:14:14 spla-repro volumio[19088]: Capabilities: volume volume-joined Aug 25 14:14:14 spla-repro volumio[19088]: Playback channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Capture channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Limits: 0 - 248 Aug 25 14:14:14 spla-repro volumio[19088]: Mono: 112 [45%] Aug 25 14:14:14 spla-repro volumio[19088]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::pushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::updateTrackBlock Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrackBlock Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::setRepeat null single undefined Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::pushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::setRandom null Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::pushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:14 spla-repro volumio[19088]: info: Setting Device type: Raspberry PI Aug 25 14:14:14 spla-repro volumio[19088]: info: Completed loading Core Plugins Aug 25 14:14:14 spla-repro volumio[19088]: info: Preparing to generate the ALSA configuration file Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787660050 101 Aug 25 14:14:14 spla-repro volumio[19088]: 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 25 14:14:14 spla-repro volumio[19088]: Unable to parse: Aug 25 14:14:14 spla-repro volumio[19088]: Simple mixer control 'Master',0 Aug 25 14:14:14 spla-repro volumio[19088]: Capabilities: volume volume-joined Aug 25 14:14:14 spla-repro volumio[19088]: Playback channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Capture channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Limits: 0 - 248 Aug 25 14:14:14 spla-repro volumio[19088]: Mono: 112 [45%] Aug 25 14:14:14 spla-repro volumio[19088]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Found device kuchyna-repro Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 14:14:14 spla-repro volumio[19088]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 25 14:14:14 spla-repro volumio[19088]: info: Listing playlists Aug 25 14:14:14 spla-repro volumio[19088]: info: Listing playlists Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Found device kupelna-repro Aug 25 14:14:14 spla-repro volumio[19088]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 14:14:14 spla-repro volumio[19088]: 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 25 14:14:14 spla-repro volumio[19088]: Unable to parse: Aug 25 14:14:14 spla-repro volumio[19088]: Simple mixer control 'Master',0 Aug 25 14:14:14 spla-repro volumio[19088]: Capabilities: volume volume-joined Aug 25 14:14:14 spla-repro volumio[19088]: Playback channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Capture channels: Mono Aug 25 14:14:14 spla-repro volumio[19088]: Limits: 0 - 248 Aug 25 14:14:14 spla-repro volumio[19088]: Mono: 112 [45%] Aug 25 14:14:14 spla-repro volumio[19088]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreStateMachine::pushState Aug 25 14:14:14 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:14 spla-repro volumio[19088]: info: Asound.conf file unchanged, so no further update is needed Aug 25 14:14:14 spla-repro volumio[19088]: info: Output device has changed, restarting MPD Aug 25 14:14:14 spla-repro volumio[19088]: info: Output device has changed, restarting Shairport Sync Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:14 spla-repro volumio[19088]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:14 spla-repro sudo[19252]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:14 spla-repro volumio[19088]: info: ___________ START PLUGINS ___________ Aug 25 14:14:14 spla-repro sudo[19253]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:14 spla-repro sudo[19252]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:14:14 spla-repro sudo[19252]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:14 spla-repro sudo[19253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:14:14 spla-repro volumio[19088]: info: ControllerMpd::onStart: Initializing MPD Aug 25 14:14:14 spla-repro sudo[19252]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:14 spla-repro sudo[19253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:14 spla-repro volumio[19088]: info: Creating MPD Configuration file Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:14 spla-repro volumio[19088]: info: [1787660054928] CoreMusicLibrary::Adding element Mediálne servery Aug 25 14:14:14 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:14 spla-repro sudo[19263]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:14 spla-repro volumio[19088]: info: UPNP Browser: Client initialized successfully Aug 25 14:14:14 spla-repro sudo[19263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:14:14 spla-repro sudo[19263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:14 spla-repro sudo[19265]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:14 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 14:14:14 spla-repro sudo[19263]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:14 spla-repro sudo[19265]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:14:14 spla-repro sudo[19265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:15 spla-repro sudo[19260]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:15 spla-repro sudo[19260]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 14:14:15 spla-repro sudo[19260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:15 spla-repro volumio[19088]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:15 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:15 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:14:15 spla-repro systemd[1]: mpd.service: Consumed 4.233s CPU time. Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:15 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:14:15 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:14:15 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:14:15 spla-repro volumio[19088]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:15 spla-repro volumio[19088]: info: [1787660055145] CoreMusicLibrary::Adding element Last_100 Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:15 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:15 spla-repro volumio[19088]: info: [1787660055153] CoreMusicLibrary::Adding element Webradio Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:15 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:14:15 spla-repro volumio[19088]: info: Initializing BBC Radios Aug 25 14:14:15 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:14:15 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:14:15 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:14:15 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:14:15 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:15 spla-repro volumio[19088]: info: Creating Spotify config file Aug 25 14:14:15 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:15 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:14:15 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:14:15 spla-repro sudo[19260]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:15 spla-repro sudo[19293]: root : unable to resolve host spla-repro: System error Aug 25 14:14:15 spla-repro sudo[19293]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:15 spla-repro sudo[19293]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 14:14:15 spla-repro sudo[19293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 14:14:15 spla-repro sudo[19293]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:15 spla-repro volumio[19088]: info: Volumio Calling Home Aug 25 14:14:15 spla-repro volumio[19211]: Starting albumart workers Aug 25 14:14:16 spla-repro volumio[19213]: Starting albumart workers Aug 25 14:14:16 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:16.142+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 25 14:14:16 spla-repro volumio[19212]: Starting albumart workers Aug 25 14:14:16 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:14:16 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:16 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: Found device Spálňa-repro Aug 25 14:14:16 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:16 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: Found device Spálňa-repro Aug 25 14:14:16 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:16 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 14:14:16 spla-repro volumio[19088]: info: MPD Permissions set Aug 25 14:14:16 spla-repro volumio[19088]: info: MPD Permissions set Aug 25 14:14:16 spla-repro volumio[19088]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 14:14:16 spla-repro volumio[19088]: info: Volumio called home Aug 25 14:14:16 spla-repro volumio[19088]: info: Spotify config file written Aug 25 14:14:16 spla-repro sudo[19301]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:17 spla-repro sudo[19301]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 14:14:17 spla-repro sudo[19301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:17 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:17 spla-repro go-librespot[19309]: go-librespot daemon starting... Aug 25 14:14:17 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:17 spla-repro volumio[19088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 25 14:14:17 spla-repro sudo[19301]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="app state loaded" Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:17 spla-repro volumio[19088]: info: No need to fix Spotify hosts Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:14:17 spla-repro volumio[19088]: info: New Spotify access tokenBQAv0Hr5ni... Aug 25 14:14:17 spla-repro volumio[19088]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:17 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:17 spla-repro volumio[19088]: info: Starting Shairport Sync Aug 25 14:14:17 spla-repro volumio[19088]: info: Starting Shairport Sync Aug 25 14:14:17 spla-repro volumio[19088]: info: Starting Shairport Sync Aug 25 14:14:17 spla-repro sudo[19343]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:17 spla-repro sudo[19345]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:17 spla-repro sudo[19345]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:17 spla-repro sudo[19345]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:17 spla-repro sudo[19343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:17 spla-repro sudo[19343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:17 spla-repro sudo[19347]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:17 spla-repro sudo[19347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:17 spla-repro sudo[19347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=info msg="zeroconf server listening on port 43143" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:17 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:17 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 14:14:17 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 14:14:17 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:14:17 spla-repro systemd[1]: shairport-sync.service: Consumed 1.890s CPU time. Aug 25 14:14:17 spla-repro volumio[19088]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 14:14:17 spla-repro volumio[19088]: info: Spotify Successfully logged in Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:17 spla-repro volumio[19088]: info: [1787660057778] CoreMusicLibrary::Adding element Spotify Aug 25 14:14:17 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="obtained new client token: AAGSygXRQEpmxqAkwZV/QfPgtyUxXo6+Jh0Xe6V6tEDHpbO6apvHcXESKelyGfu4xYAv7zSp8ghCplRn3IwDz9yfS79M7Ec+DmjwKhbEsgOmzCUgCsf9IxPsWQdagoNRoCX2epngCfeluv8Rb0bdarGH2Xa4nYt5Hh2bEXS3uKjJyzEroDFLYT59dKfGuB8iJrFJHx5PSpUtzEX21ZepoHF9QlsIfEeQBxQwd+Ro7PZZDj7MsKDRo06blg==" Aug 25 14:14:17 spla-repro volumio[19088]: Cannot find translation for source Spotify Aug 25 14:14:17 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:14:17 spla-repro sudo[19343]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:17 spla-repro sudo[19345]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:17 spla-repro sudo[19347]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:17 spla-repro volumio[19088]: info: Shairport-Sync Started Aug 25 14:14:17 spla-repro volumio[19088]: Error adding Membership: Error: addMembership EINVAL Aug 25 14:14:17 spla-repro volumio[19088]: info: Shairport-Sync Started Aug 25 14:14:17 spla-repro volumio[19088]: info: Shairport-Sync Started Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=debug msg="completed challenge" Aug 25 14:14:17 spla-repro go-librespot[19317]: time="2026-08-25T14:14:17+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:18 spla-repro go-librespot[19317]: time="2026-08-25T14:14:18+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:18 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:18 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:19 spla-repro mpd[19295]: 2026-08-25T14:14:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 14:14:19 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 14:14:19 spla-repro sudo[19253]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:19 spla-repro sudo[19265]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:19 spla-repro volumio[19088]: info: Completed starting Core Plugins Aug 25 14:14:19 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:19 spla-repro volumio[19088]: info: ----- MyVolumio plugins startup ---- Aug 25 14:14:19 spla-repro volumio[19088]: info: ------------------------------------------- Aug 25 14:14:19 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 14:14:19 spla-repro volumio[19088]: error: MPD error: The expression evaluated to a falsy value: Aug 25 14:14:19 spla-repro volumio[19088]: assert.ok(self.idling) Aug 25 14:14:19 spla-repro volumio[19088]: error: The expression evaluated to a falsy value: Aug 25 14:14:19 spla-repro volumio[19088]: assert.ok(self.idling) Aug 25 14:14:19 spla-repro volumio[19088]: info: MPD running with PID19295 Aug 25 14:14:19 spla-repro volumio[19088]: ,establishing connection Aug 25 14:14:19 spla-repro volumio[19088]: error: updateQueue error: null Aug 25 14:14:19 spla-repro volumio[19088]: error: updateQueue error: null Aug 25 14:14:20 spla-repro sudo[19386]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:20 spla-repro sudo[19386]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:14:20 spla-repro sudo[19386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:20 spla-repro sudo[19388]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:20 spla-repro sudo[19386]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:20 spla-repro sudo[19388]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:14:20 spla-repro sudo[19388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:20 spla-repro sudo[19388]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:20 spla-repro sudo[19391]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:20 spla-repro sudo[19391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 14:14:20 spla-repro sudo[19391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:20 spla-repro sudo[19391]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:20 spla-repro volumio[19088]: info: Upmpdcli Daemon Started Aug 25 14:14:20 spla-repro volumio[19088]: info: go-librespot daemon successfully initialized Aug 25 14:14:20 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:20 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:21 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 25 14:14:21 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:21 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:21 spla-repro go-librespot[19394]: go-librespot daemon starting... Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="app state loaded" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=info msg="zeroconf server listening on port 40157" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="obtained new client token: AAETslOhyNhIvHLY7PunSxxiJgSkiDhyWmOOFciG7fyintPumX131ZWJQ5hogFN5GSvo/D7SZ51J2bUF3HrgiDcdpWR0LVFzYMxI8Z0X4AMjFCKDc2Gy8ZggZB9Vm6RHmul2viClKQ+OY80pNzd6k9deGHD/Ztgb2g8D3NcGiNSWjwF5Yx5FF0bIU3vhwayLhR6JXItwbx8lINn4ORfmWM30gW3UzLC+yO0ncrHrN8SOx1lhNVYuKX9X3g==" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=debug msg="completed challenge" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:21 spla-repro go-librespot[19395]: time="2026-08-25T14:14:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:21 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:21 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:23 spla-repro volumio[19088]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:23 spla-repro volumio[19088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:24 spla-repro volumio[19088]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 14:14:24 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 25 14:14:24 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:25 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:25 spla-repro go-librespot[19404]: go-librespot daemon starting... Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="app state loaded" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14: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-gae2.spotify.com:80]" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=info msg="zeroconf server listening on port 45075" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="obtained new client token: AAE37J5jCRVGLCUYf4OGoI+qqL+qQZx9RP14/3cJPu4XFfebiWzEuivk6b8gZnny/rH57C9WJwsebjG/U137oCg9LCYJJXPffaOZESwQUtzsXAZUpYF4PsJ5672/bLlhGLPxuMNpJsP51zyUmMum015MPnxzdmwk6e2tg+WfK7ZRwid1l579M9SIg9ahZpPfTPTGJoNQPqPibEow9DIVCx/K19KefSkPm3i6KDyUYA7HJvgPHYvFP2NMnQ==" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=debug msg="completed challenge" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:25 spla-repro go-librespot[19405]: time="2026-08-25T14:14:25+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:25 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:25 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:26 spla-repro volumio[19088]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:26 spla-repro volumio[19088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 14:14:28 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 14:14:28 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Aug 25 14:14:28 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:28 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:28 spla-repro go-librespot[19414]: go-librespot daemon starting... Aug 25 14:14:28 spla-repro go-librespot[19415]: time="2026-08-25T14:14:28+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:28 spla-repro go-librespot[19415]: time="2026-08-25T14:14:28+02:00" level=debug msg="app state loaded" Aug 25 14:14:28 spla-repro go-librespot[19415]: time="2026-08-25T14:14:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:29 spla-repro volumio[19088]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 14:14:29 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 14:14:29 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:29 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:29 spla-repro volumio[19088]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 14:14:29 spla-repro volumio[19088]: info: MyVolumio login type: Token Aug 25 14:14:29 spla-repro volumio[19088]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 14:14:29 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=info msg="zeroconf server listening on port 38751" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="obtained new client token: AAHnnkGiBoXBFcULFGi0wYVczau0WP68Dm8ohZHnpKV+wz1Xqq4tFz0EISmOZM1YvASAGc5BGRyAYCi7dg/DHQj5+5Lqn+QbD5fc+IS+DsLapxPeSx9neksNnW8jTjwdX5k0cg5GRpJRl47W2cfpDLSkyW4BXyV2LN497oAkIiLHfC5HN9PX7i9+N8aQh1/GKg0KgnUxrGuvYbVuK2xWU9LwGzS7ntWvTq7N7Xjf/V2MLn8pC29/oDPRdQ==" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=debug msg="completed challenge" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:29 spla-repro go-librespot[19415]: time="2026-08-25T14:14:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:29 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:30 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 14:14:30 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 14:14:30 spla-repro volumio[19088]: info: Streaming services startup Aug 25 14:14:30 spla-repro volumio[19088]: info: Starting Streaming Daemon Aug 25 14:14:30 spla-repro sudo[19439]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:30 spla-repro volumio[19088]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 14:14:30 spla-repro sudo[19439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 14:14:30 spla-repro sudo[19439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:30 spla-repro sudo[19439]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:30 spla-repro volumio[19088]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:30 spla-repro volumio[19088]: error: Cannot start Volumio Streaming Daemon Aug 25 14:14:30 spla-repro volumio[19088]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 14:14:30 spla-repro volumio[19088]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:30 spla-repro volumio[19088]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 14:14:30 spla-repro volumio[19088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:30 spla-repro volumio[19088]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:30 spla-repro volumio[19088]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:30 spla-repro volumio[19088]: info: Listing playlists Aug 25 14:14:30 spla-repro volumio[19088]: info: Listing playlists Aug 25 14:14:30 spla-repro volumio[19088]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 25 14:14:31 spla-repro volumio[19088]: info: MyVolumio token set successfully Aug 25 14:14:31 spla-repro volumio[19088]: info: MYVOLUMIO: Adding device Aug 25 14:14:31 spla-repro volumio[19088]: info: MYVOLUMIO: Evaluating Server Aug 25 14:14:31 spla-repro volumio[19088]: info: MyVolumio status changed Aug 25 14:14:31 spla-repro volumio[19088]: info: Streaming services startup Aug 25 14:14:31 spla-repro volumio[19088]: info: Starting Streaming Daemon Aug 25 14:14:31 spla-repro volumio[19088]: info: Removing browser output: myVolumio user plan is not superstar Aug 25 14:14:31 spla-repro volumio[19088]: info: Removing audio output: Aug 25 14:14:31 spla-repro volumio[19088]: info: Stoppping Tunnel 1 Aug 25 14:14:31 spla-repro sudo[19466]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:31 spla-repro sudo[19466]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 14:14:31 spla-repro sudo[19466]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:31 spla-repro sudo[19466]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:31 spla-repro sudo[19469]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:31 spla-repro volumio[19088]: error: Cannot start Volumio Streaming Daemon Aug 25 14:14:31 spla-repro sudo[19469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 25 14:14:31 spla-repro sudo[19469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:31 spla-repro volumio[19088]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 14:14:31 spla-repro volumio[19088]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:31 spla-repro volumio[19088]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:14:31 spla-repro sudo[19469]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:31 spla-repro volumio[19088]: info: Remote SSH Stopped Aug 25 14:14:31 spla-repro volumio[19088]: info: Setting Geolocation for MyVolumio to eu7 Aug 25 14:14:31 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:31 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:31 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:32 spla-repro volumio[19088]: info: Successfully Added MyVolumio device Aug 25 14:14:32 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Aug 25 14:14:32 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:32 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:32 spla-repro go-librespot[19471]: go-librespot daemon starting... Aug 25 14:14:32 spla-repro go-librespot[19472]: time="2026-08-25T14:14:32+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:32 spla-repro go-librespot[19472]: time="2026-08-25T14:14:32+02:00" level=debug msg="app state loaded" Aug 25 14:14:32 spla-repro volumio[19088]: info: Updating MyVolumio device info Aug 25 14:14:32 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:32 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:32 spla-repro volumio[19088]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:32 spla-repro go-librespot[19472]: time="2026-08-25T14:14:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=info msg="zeroconf server listening on port 39891" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:33 spla-repro volumio[19088]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="obtained new client token: AAGO/uhmL96pBTK5Bzau+xq4IV/bUEEPOkMG6alYYhgckU1K8KU+GR5zOXtyy0n3ngCx5hNh0uKWkn639xgzOIWAIpN0f5Lfhn9/MLYhvVqpq/bYy++a/gyYwaOZiOm/+rl/gpGJ0gZjlQdOVETV6uMZrjh3sz3hNRqMma4JetfF0IprrwMEIT7MHEanixQ/NBAYivmcw2mx8Hh2rkgfCOgwq1leyqYJqKZz8B7hRJ4C1QfqAJ705Y0=" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="new websocket client" Aug 25 14:14:33 spla-repro volumio[19088]: info: Connection to go-librespot Websocket established Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=debug msg="completed challenge" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:33 spla-repro go-librespot[19472]: time="2026-08-25T14:14:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:33 spla-repro volumio[19088]: info: Connection to go-librespot Websocket closed Aug 25 14:14:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:33 spla-repro volumio[19088]: info: Successfully Updated MyVolumio device Aug 25 14:14:36 spla-repro volumio[19088]: info: Getting Spotify volume Aug 25 14:14:36 spla-repro volumio[19088]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:14:36 spla-repro volumio[19088]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:36 spla-repro volumio[19088]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 14:14:36 spla-repro volumio[19088]: errno: -111, Aug 25 14:14:36 spla-repro volumio[19088]: code: 'ECONNREFUSED', Aug 25 14:14:36 spla-repro volumio[19088]: syscall: 'connect', Aug 25 14:14:36 spla-repro volumio[19088]: address: '127.0.0.1', Aug 25 14:14:36 spla-repro volumio[19088]: port: 9879, Aug 25 14:14:36 spla-repro volumio[19088]: response: undefined Aug 25 14:14:36 spla-repro volumio[19088]: } Aug 25 14:14:36 spla-repro volumio[19088]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:14:36 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Aug 25 14:14:36 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:36 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:36 spla-repro go-librespot[19494]: go-librespot daemon starting... Aug 25 14:14:36 spla-repro go-librespot[19495]: time="2026-08-25T14:14:36+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:36 spla-repro go-librespot[19495]: time="2026-08-25T14:14:36+02:00" level=debug msg="app state loaded" Aug 25 14:14:36 spla-repro go-librespot[19495]: time="2026-08-25T14:14:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:37 spla-repro sudo[19506]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:37 spla-repro sudo[19506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 14:13' Aug 25 14:14:37 spla-repro sudo[19506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=info msg="zeroconf server listening on port 45119" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="obtained new client token: AAF7CliS1EuGICR5iDac59Y/RYzdXgMF2fI7zcM4opkBW+E/BkB1mWkaH3j+j3QYTaG1/l5Fon0tk9pukyLl6aW/M4QQbs0OJyPsmrwm+WaEDMlLtiPL8nPaFwxUBQWpAjRbPhVhnzVXnLqe67s7ieOUNALJ+4J8qN02tbxQPDyDBMwiyLczmtA8oCLm0WvYJzw/9ECakADA3FeLuqXAXe5bcjX8t+FyjX+k56CAob4UmG9EO/h7Sg4=" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:37 spla-repro sudo[19506]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=debug msg="completed challenge" Aug 25 14:14:37 spla-repro volumio[19088]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:37 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:37.442+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 25 14:14:37 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:37] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 25 14:14:37 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:37] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 25 14:14:37 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:37 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:37.447+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:14:37 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 25 14:14:37 spla-repro systemd[1]: volumio.service: Consumed 28.368s CPU time. Aug 25 14:14:37 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:14:37 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:14:37 spla-repro go-librespot[19495]: time="2026-08-25T14:14:37+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:37 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:37 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:37 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5437. Aug 25 14:14:37 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:14:37 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 25 14:14:37 spla-repro systemd[1]: volumio.service: Consumed 28.368s CPU time. Aug 25 14:14:37 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 25 14:14:37 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:14:38 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:38.449+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:14:39 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:39 spla-repro volumio[19520]: info: ----- Volumio3 ---- Aug 25 14:14:39 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:39 spla-repro volumio[19520]: info: ----- System startup ---- Aug 25 14:14:39 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:40 spla-repro volumio[19520]: info: MYVOLUMIO Environment detected Aug 25 14:14:40 spla-repro volumio[19520]: info: Plugin folders cleanup Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning into folder /volumio/app/plugins/ Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category audio_interface Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category miscellanea Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category music_service Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category plugins.json Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category system_controller Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category user_interface Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning into folder /data/plugins/ Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category audio_interface Aug 25 14:14:40 spla-repro volumio[19520]: info: Scanning category music_service Aug 25 14:14:40 spla-repro volumio[19520]: info: Plugin folders cleanup completed Aug 25 14:14:40 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:40 spla-repro volumio[19520]: info: ----- Core plugins startup ---- Aug 25 14:14:40 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:40 spla-repro volumio[19520]: info: Loading plugins from folder /volumio/app/plugins/ Aug 25 14:14:40 spla-repro volumio[19520]: info: Adding plugin upnp to MyMusic Plugins Aug 25 14:14:40 spla-repro volumio[19520]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 25 14:14:40 spla-repro volumio[19520]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 25 14:14:40 spla-repro volumio[19520]: info: Loading plugins from folder /data/plugins/ Aug 25 14:14:40 spla-repro volumio[19520]: info: Loading plugin "system"... Aug 25 14:14:40 spla-repro volumio[19520]: info: Loading plugin "appearance"... Aug 25 14:14:40 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Aug 25 14:14:40 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:40 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:40 spla-repro go-librespot[19549]: go-librespot daemon starting... Aug 25 14:14:40 spla-repro go-librespot[19550]: time="2026-08-25T14:14:40+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:40 spla-repro go-librespot[19550]: time="2026-08-25T14:14:40+02:00" level=debug msg="app state loaded" Aug 25 14:14:40 spla-repro go-librespot[19550]: time="2026-08-25T14:14:40+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=info msg="zeroconf server listening on port 38481" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="obtained new client token: AAHc/yb9EkSSenGu/CdkungDDBCTNioUayOX+o721mnc1BQsz1oUlYU4YhdD0LuRPtijdGY2T6dyu8xM5S1e8B5jVcst9FyMMoTEZpYnSRIYjVZMObdmgJela+4XXEiilgy1AnjAvEq59kP+hZkY7MRIQZcTM5D6uTu648dyvtjSreGC+TiJvhi7Ws/hntRIe7UDDih1FIuQrS5N1FzpQoZpcp4+IdLnU1/BGSTdw+yCgHjkIUJaYxE=" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=debug msg="completed challenge" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:41 spla-repro go-librespot[19550]: time="2026-08-25T14:14:41+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:41 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:41 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "network"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Refreshing Cached IP Addresses Aug 25 14:14:41 spla-repro sudo[19560]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:41 spla-repro sudo[19562]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:41 spla-repro sudo[19560]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:14:41 spla-repro sudo[19560]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:41 spla-repro sudo[19562]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:14:41 spla-repro sudo[19562]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:41 spla-repro sudo[19560]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "services"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "volumio5onboarding"... Aug 25 14:14:41 spla-repro sudo[19562]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:41 spla-repro sudo[19569]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:41 spla-repro sudo[19569]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 25 14:14:41 spla-repro sudo[19569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "alsa_controller"... Aug 25 14:14:41 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "wizard"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "networkfs"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Starting Udev Watcher for removable devices Aug 25 14:14:41 spla-repro volumio[19520]: info: Ignoring mount for partition: boot Aug 25 14:14:41 spla-repro volumio[19520]: info: Ignoring mount for partition: volumio Aug 25 14:14:41 spla-repro volumio[19520]: info: Ignoring mount for partition: volumio_data Aug 25 14:14:41 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "volumio_command_line_client"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "upnp"... Aug 25 14:14:41 spla-repro volumio[19520]: info: [1787660081814] Starting Upmpd Daemon Aug 25 14:14:41 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "my_music"... Aug 25 14:14:41 spla-repro volumio[19520]: info: Loading plugin "mpd"... Aug 25 14:14:42 spla-repro volumio[19520]: info: Loading plugin "upnp_browser"... Aug 25 14:14:42 spla-repro sudo[19569]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:42 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:42] [connect] Successful connection Aug 25 14:14:43 spla-repro volumio[19520]: info: Starting UPNP Browser Aug 25 14:14:43 spla-repro volumio[19520]: info: Loading plugin "alarm-clock"... Aug 25 14:14:43 spla-repro volumio[19520]: info: Loading plugin "airplay_emulation"... Aug 25 14:14:43 spla-repro volumio[19520]: info: Starting Shairport Sync Aug 25 14:14:43 spla-repro volumio[19520]: info: Loading plugin "last_100"... Aug 25 14:14:43 spla-repro volumio[19520]: info: Loading plugin "webradio"... Aug 25 14:14:43 spla-repro volumio[19520]: info: Loading plugin "i2s_dacs"... Aug 25 14:14:44 spla-repro volumio[19520]: info: Loading plugin "volumiodiscovery"... Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** For more information see Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:44 spla-repro volumio[19520]: *** WARNING *** For more information see Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** For more information see Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:14:44 spla-repro node[19520]: *** WARNING *** For more information see Aug 25 14:14:44 spla-repro volumio[19520]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 25 14:14:44 spla-repro volumio[19520]: info: Discovery: Started advertising with name: Spálňa-repro Aug 25 14:14:44 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:14:44 spla-repro volumio[19520]: info: Loading plugin "spop"... Aug 25 14:14:44 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Aug 25 14:14:44 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:44 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:44 spla-repro go-librespot[19595]: go-librespot daemon starting... Aug 25 14:14:44 spla-repro go-librespot[19596]: time="2026-08-25T14:14:44+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:44 spla-repro go-librespot[19596]: time="2026-08-25T14:14:44+02:00" level=debug msg="app state loaded" Aug 25 14:14:44 spla-repro go-librespot[19596]: time="2026-08-25T14:14:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=info msg="zeroconf server listening on port 41979" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "outputs"... Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "albumart"... Aug 25 14:14:45 spla-repro volumio[19520]: info: Plugin example_plugin is not enabled Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "inputs"... Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "updater_comm"... Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="obtained new client token: AAG6Y8LHJ2pJ6zFE9/rTGdodAwCv8frp8Wmn6bcUONy/VXJwZCZIkS7Cb5jZecMlayvU5ipRKr2AVGHVvl25Lf+b/0kEu83XjD9xvucThKtYuF/D1gSVbx8u82BZTSl4MUgGSfulPQVFmCCqfkkxWCEo+5/Rwc4fRKcHNrWNh1vKlfAQyvMpQYLDm5LL95tUMVz2ySBsr99BxUpocZCF0G0vhZ7X+TKRF167szy8/S9T5a/fPgiPB80=" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=debug msg="completed challenge" Aug 25 14:14:45 spla-repro volumio[19520]: info: Plugin mpdemulation is not enabled Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "rest_api"... Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading plugin "websocket"... Aug 25 14:14:45 spla-repro volumio[19520]: info: Starting Socket.io Server version 1.7.4 Aug 25 14:14:45 spla-repro volumio[19520]: info: Plugin fusiondsp is not enabled Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:45 spla-repro volumio[19520]: info: Loading i18n strings for locale sk Aug 25 14:14:45 spla-repro volumio[19520]: Updating browse sources language Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:45 spla-repro go-librespot[19596]: time="2026-08-25T14:14:45+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:45 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:45 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::initPlayerControls Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:45 spla-repro volumio[19520]: Express server listening on port 3000 Aug 25 14:14:45 spla-repro volumio[19520]: [Metrics] WebUI: 6s 575.91ms Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreStateMachine::resetVolumioState Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreStateMachine::getcurrentVolume Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:14:45 spla-repro volumio[19520]: info: Cannot read play queue from file Aug 25 14:14:45 spla-repro volumio[19520]: info: Volumio Network Manager: Network status updated: 1 Aug 25 14:14:45 spla-repro volumio[19520]: Unable to parse: Aug 25 14:14:45 spla-repro volumio[19520]: Simple mixer control 'Master',0 Aug 25 14:14:45 spla-repro volumio[19520]: Capabilities: volume volume-joined Aug 25 14:14:45 spla-repro volumio[19520]: Playback channels: Mono Aug 25 14:14:45 spla-repro volumio[19520]: Capture channels: Mono Aug 25 14:14:45 spla-repro volumio[19520]: Limits: 0 - 248 Aug 25 14:14:45 spla-repro volumio[19520]: Mono: 112 [45%] Aug 25 14:14:45 spla-repro volumio[19520]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:14:45 spla-repro volumio[19605]: Forking 3 albumart workers Aug 25 14:14:45 spla-repro volumio[19520]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 25 14:14:45 spla-repro volumio[19520]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 25 14:14:45 spla-repro volumio[19520]: info: Received Get System Info Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 14:14:45 spla-repro volumio[19520]: info: Discovery: Getting this device information Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:45 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 14:14:45 spla-repro volumio[19520]: 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 25 14:14:45 spla-repro volumio[19520]: Unable to parse: Aug 25 14:14:45 spla-repro volumio[19520]: Simple mixer control 'Master',0 Aug 25 14:14:45 spla-repro volumio[19520]: Capabilities: volume volume-joined Aug 25 14:14:45 spla-repro volumio[19520]: Playback channels: Mono Aug 25 14:14:45 spla-repro volumio[19520]: Capture channels: Mono Aug 25 14:14:45 spla-repro volumio[19520]: Limits: 0 - 248 Aug 25 14:14:45 spla-repro volumio[19520]: Mono: 112 [45%] Aug 25 14:14:45 spla-repro volumio[19520]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreStateMachine::pushState Aug 25 14:14:45 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreStateMachine::updateTrackBlock Aug 25 14:14:45 spla-repro volumio[19520]: info: CorePlayQueue::getTrackBlock Aug 25 14:14:45 spla-repro volumio[19520]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 14:14:46 spla-repro volumio[19520]: 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 25 14:14:46 spla-repro volumio[19520]: info: CoreStateMachine::setRepeat null single undefined Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreStateMachine::pushState Aug 25 14:14:46 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreStateMachine::setRandom null Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreStateMachine::pushState Aug 25 14:14:46 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:46 spla-repro volumio[19520]: info: Setting Device type: Raspberry PI Aug 25 14:14:46 spla-repro volumio[19520]: info: Completed loading Core Plugins Aug 25 14:14:46 spla-repro volumio[19520]: info: Preparing to generate the ALSA configuration file Aug 25 14:14:46 spla-repro volumio[19520]: Unable to parse: Aug 25 14:14:46 spla-repro volumio[19520]: Simple mixer control 'Master',0 Aug 25 14:14:46 spla-repro volumio[19520]: Capabilities: volume volume-joined Aug 25 14:14:46 spla-repro volumio[19520]: Playback channels: Mono Aug 25 14:14:46 spla-repro volumio[19520]: Capture channels: Mono Aug 25 14:14:46 spla-repro volumio[19520]: Limits: 0 - 248 Aug 25 14:14:46 spla-repro volumio[19520]: Mono: 112 [45%] Aug 25 14:14:46 spla-repro volumio[19520]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:46 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:46 spla-repro volumio-remote-updater[725]: [2026-08-25 14:14:46] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787660082 101 Aug 25 14:14:46 spla-repro volumio[19520]: 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 25 14:14:46 spla-repro volumio[19520]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 14:14:46 spla-repro volumio[19520]: info: Discovery: Found device kuchyna-repro Aug 25 14:14:46 spla-repro volumio[19520]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 14:14:46 spla-repro volumio[19520]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 25 14:14:46 spla-repro volumio[19520]: Unable to parse: Aug 25 14:14:46 spla-repro volumio[19520]: Simple mixer control 'Master',0 Aug 25 14:14:46 spla-repro volumio[19520]: Capabilities: volume volume-joined Aug 25 14:14:46 spla-repro volumio[19520]: Playback channels: Mono Aug 25 14:14:46 spla-repro volumio[19520]: Capture channels: Mono Aug 25 14:14:46 spla-repro volumio[19520]: Limits: 0 - 248 Aug 25 14:14:46 spla-repro volumio[19520]: Mono: 112 [45%] Aug 25 14:14:46 spla-repro volumio[19520]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreStateMachine::pushState Aug 25 14:14:46 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioPushState Aug 25 14:14:46 spla-repro volumio[19520]: info: Listing playlists Aug 25 14:14:46 spla-repro volumio[19520]: info: Listing playlists Aug 25 14:14:46 spla-repro volumio[19520]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 14:14:46 spla-repro volumio[19520]: info: Discovery: Found device kupelna-repro Aug 25 14:14:46 spla-repro volumio[19520]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 14:14:46 spla-repro volumio[19520]: 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 25 14:14:46 spla-repro volumio[19520]: info: Asound.conf file unchanged, so no further update is needed Aug 25 14:14:46 spla-repro volumio[19520]: info: Output device has changed, restarting MPD Aug 25 14:14:46 spla-repro volumio[19520]: info: Output device has changed, restarting Shairport Sync Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:46 spla-repro sudo[19663]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:46 spla-repro sudo[19663]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:14:46 spla-repro sudo[19663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:46 spla-repro sudo[19664]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:46 spla-repro sudo[19663]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:46 spla-repro sudo[19664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:14:46 spla-repro volumio[19520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:46 spla-repro sudo[19664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:46 spla-repro volumio[19520]: info: ___________ START PLUGINS ___________ Aug 25 14:14:46 spla-repro volumio[19520]: info: ControllerMpd::onStart: Initializing MPD Aug 25 14:14:46 spla-repro volumio[19520]: info: Creating MPD Configuration file Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:46 spla-repro volumio[19520]: info: [1787660086607] CoreMusicLibrary::Adding element Mediálne servery Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:46 spla-repro sudo[19675]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:46 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 14:14:46 spla-repro sudo[19672]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:46 spla-repro sudo[19675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:14:46 spla-repro sudo[19675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:46 spla-repro sudo[19672]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 14:14:46 spla-repro sudo[19672]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:46 spla-repro volumio[19520]: info: UPNP Browser: Client initialized successfully Aug 25 14:14:46 spla-repro sudo[19676]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:46 spla-repro sudo[19676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:14:46 spla-repro sudo[19676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:46 spla-repro sudo[19675]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:46 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:14:46 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:14:46 spla-repro systemd[1]: mpd.service: Consumed 3.927s CPU time. Aug 25 14:14:46 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:46 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:14:46 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:14:46 spla-repro volumio[19520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:46 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:14:46 spla-repro volumio[19520]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:46 spla-repro volumio[19520]: info: [1787660086825] CoreMusicLibrary::Adding element Last_100 Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:46 spla-repro volumio[19520]: info: [1787660086837] CoreMusicLibrary::Adding element Webradio Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:46 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:46 spla-repro volumio[19520]: info: Initializing BBC Radios Aug 25 14:14:46 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:14:46.866+02:00 level=INFO msg="service successfully established" component=discovery/localnet Aug 25 14:14:46 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:14:46 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:14:46 spla-repro sudo[19672]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:46 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:14:46 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:14:46 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:46 spla-repro volumio[19520]: info: Creating Spotify config file Aug 25 14:14:46 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:47 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:14:47 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:14:47 spla-repro sudo[19705]: root : unable to resolve host spla-repro: System error Aug 25 14:14:47 spla-repro sudo[19705]: sudo: unable to resolve host spla-repro: System error Aug 25 14:14:47 spla-repro sudo[19705]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 14:14:47 spla-repro sudo[19705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 14:14:47 spla-repro sudo[19705]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:47 spla-repro volumio[19520]: info: Volumio Calling Home Aug 25 14:14:47 spla-repro volumio[19623]: Starting albumart workers Aug 25 14:14:47 spla-repro volumio[19624]: Starting albumart workers Aug 25 14:14:47 spla-repro volumio[19621]: Starting albumart workers Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:48 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: Found device Spálňa-repro Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:48 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 14:14:48 spla-repro volumio[19520]: info: MPD Permissions set Aug 25 14:14:48 spla-repro volumio[19520]: info: MPD Permissions set Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: Found device Spálňa-repro Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:48 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:48 spla-repro volumio[19520]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 14:14:48 spla-repro volumio[19520]: info: Volumio called home Aug 25 14:14:48 spla-repro volumio[19520]: info: Spotify config file written Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:48 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:48 spla-repro sudo[19712]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:48 spla-repro sudo[19712]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 14:14:48 spla-repro sudo[19712]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:48 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:48 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:48 spla-repro go-librespot[19714]: go-librespot daemon starting... Aug 25 14:14:48 spla-repro sudo[19712]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:48 spla-repro volumio[19520]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 25 14:14:48 spla-repro go-librespot[19716]: time="2026-08-25T14:14:48+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:48 spla-repro go-librespot[19716]: time="2026-08-25T14:14:48+02:00" level=debug msg="app state loaded" Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro go-librespot[19716]: time="2026-08-25T14:14:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:14:48 spla-repro volumio[19520]: info: No need to fix Spotify hosts Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=info msg="zeroconf server listening on port 33243" Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:49 spla-repro volumio[19520]: info: New Spotify access tokenBQDkqs3AeF... Aug 25 14:14:49 spla-repro volumio[19520]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="obtained new client token: AAG3w8o/zROU2SXcusg06h4CI6tH36iLEORqZLQGVCjEpXY5IK/aqCeFI6VvzBkUWIYEQD0T8Dkt0dwxLj0iijEOl6GGtIudWtPrpXIYGRI4hH2Aby3pd3rWKvoJ3Iz1Nqi4GAAAR88Y9gW5lfXECmddSQnCAU+vzoM01szsURsyaiEf4SA7Y15FmNrE70hRVpwAzz2gwudBBHqDBDKZKgyXwJbq7SbNxSDUqBAT9CEri1kzVZCK6LQ=" Aug 25 14:14:49 spla-repro volumio[19520]: info: Starting Shairport Sync Aug 25 14:14:49 spla-repro volumio[19520]: info: Starting Shairport Sync Aug 25 14:14:49 spla-repro volumio[19520]: info: Starting Shairport Sync Aug 25 14:14:49 spla-repro sudo[19753]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:49 spla-repro sudo[19755]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:49 spla-repro sudo[19753]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:49 spla-repro sudo[19753]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:49 spla-repro sudo[19755]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:49 spla-repro sudo[19755]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:49 spla-repro sudo[19757]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:49 spla-repro sudo[19757]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:14:49 spla-repro sudo[19757]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=debug msg="completed challenge" Aug 25 14:14:49 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:49 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:49 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 14:14:49 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 14:14:49 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:14:49 spla-repro systemd[1]: shairport-sync.service: Consumed 1.860s CPU time. Aug 25 14:14:49 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:14:49 spla-repro sudo[19753]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:49 spla-repro sudo[19755]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:49 spla-repro sudo[19757]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:49 spla-repro go-librespot[19716]: time="2026-08-25T14:14:49+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:49 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:49 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:49 spla-repro volumio[19520]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 14:14:49 spla-repro volumio[19520]: info: Spotify Successfully logged in Aug 25 14:14:49 spla-repro volumio[19520]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:14:49 spla-repro volumio[19520]: info: [1787660089538] CoreMusicLibrary::Adding element Spotify Aug 25 14:14:49 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:14:49 spla-repro volumio[19520]: Cannot find translation for source Spotify Aug 25 14:14:49 spla-repro volumio[19520]: info: Shairport-Sync Started Aug 25 14:14:49 spla-repro volumio[19520]: Error adding Membership: Error: addMembership EINVAL Aug 25 14:14:49 spla-repro volumio[19520]: info: Shairport-Sync Started Aug 25 14:14:49 spla-repro volumio[19520]: info: Shairport-Sync Started Aug 25 14:14:50 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:14:50 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:14:51 spla-repro mpd[19707]: 2026-08-25T14:14:51 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 14:14:51 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 14:14:51 spla-repro sudo[19676]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:51 spla-repro sudo[19664]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:51 spla-repro volumio[19520]: info: Completed starting Core Plugins Aug 25 14:14:51 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:51 spla-repro volumio[19520]: info: ----- MyVolumio plugins startup ---- Aug 25 14:14:51 spla-repro volumio[19520]: info: ------------------------------------------- Aug 25 14:14:51 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 14:14:51 spla-repro volumio[19520]: error: MPD error: The expression evaluated to a falsy value: Aug 25 14:14:51 spla-repro volumio[19520]: assert.ok(self.idling) Aug 25 14:14:51 spla-repro volumio[19520]: error: The expression evaluated to a falsy value: Aug 25 14:14:51 spla-repro volumio[19520]: assert.ok(self.idling) Aug 25 14:14:51 spla-repro volumio[19520]: error: updateQueue error: null Aug 25 14:14:51 spla-repro volumio[19520]: info: MPD running with PID19707 Aug 25 14:14:51 spla-repro volumio[19520]: ,establishing connection Aug 25 14:14:51 spla-repro volumio[19520]: error: updateQueue error: null Aug 25 14:14:51 spla-repro sudo[19795]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:51 spla-repro sudo[19797]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:51 spla-repro sudo[19795]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:14:51 spla-repro sudo[19797]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:14:51 spla-repro sudo[19797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:51 spla-repro sudo[19795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:51 spla-repro sudo[19797]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:51 spla-repro sudo[19795]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:51 spla-repro sudo[19799]: volumio : unable to resolve host spla-repro: System error Aug 25 14:14:51 spla-repro sudo[19799]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 14:14:51 spla-repro sudo[19799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:14:51 spla-repro sudo[19799]: pam_unix(sudo:session): session closed for user root Aug 25 14:14:51 spla-repro volumio[19520]: info: Upmpdcli Daemon Started Aug 25 14:14:52 spla-repro volumio[19520]: info: go-librespot daemon successfully initialized Aug 25 14:14:52 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Aug 25 14:14:52 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:52 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:52 spla-repro go-librespot[19803]: go-librespot daemon starting... Aug 25 14:14:52 spla-repro go-librespot[19804]: time="2026-08-25T14:14:52+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:52 spla-repro go-librespot[19804]: time="2026-08-25T14:14:52+02:00" level=debug msg="app state loaded" Aug 25 14:14:52 spla-repro go-librespot[19804]: time="2026-08-25T14:14:52+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=info msg="zeroconf server listening on port 45119" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="obtained new client token: AAGHXb0KQIV+efVWy1zTeczzFHX9Pla5YUalqbhQRKVgR9bDgo83f7QQTZj9nCulk4R8rHjaslaPHUzQyunS6/DoPTt8ldQC2bd36+U+5Sed0aFUE4LjNNOSSuwyqXV+qqX2td+c8lCYpHikC7uTzQpGsQECzucqOB3ZB72KEzERMjoAfXSBkPt27PL2y3vqSC9Osr1zTstM0jWPUv2wcdySqiNmv1iwsvFzYHtRvPkchh7o6TF29JQ=" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=debug msg="completed challenge" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:53 spla-repro go-librespot[19804]: time="2026-08-25T14:14:53+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:53 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:53 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:55 spla-repro volumio[19520]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:55 spla-repro volumio[19520]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:56 spla-repro volumio[19520]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 14:14:56 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Aug 25 14:14:56 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:56 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:14:56 spla-repro go-librespot[19815]: go-librespot daemon starting... Aug 25 14:14:56 spla-repro go-librespot[19816]: time="2026-08-25T14:14:56+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:14:56 spla-repro go-librespot[19816]: time="2026-08-25T14:14:56+02:00" level=debug msg="app state loaded" Aug 25 14:14:56 spla-repro go-librespot[19816]: time="2026-08-25T14:14:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=info msg="zeroconf server listening on port 32873" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="obtained new client token: AAELHKiUYwYdIdNgzxI7vqSn1eSfxpNy49yMcWaZKwPcrFQcM8SO9DCEF/X9RJu69DNzjU9w286eKBkhJTuJfY4xUEkVO9R1SxB605AUYpqkAVMQbTCZpPP840BhjVtnzus23hmfYI80v45JolDtSYel0XWc15bZ6XxbrwIDVkl6q17BAB04Rmlk1l0wFfkOjPtSTxYg1IH7fkx7HlhJ22PHuBL0hKys/uXnYU1Tr6JrOk89rwPkDII=" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="completed keyexchange" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=debug msg="completed challenge" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:14:57 spla-repro go-librespot[19816]: time="2026-08-25T14:14:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:14:57 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:14:57 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:14:58 spla-repro volumio[19520]: info: Initializing connection to go-librespot Websocket Aug 25 14:14:58 spla-repro volumio[19520]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 14:14:59 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 14:15:00 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Aug 25 14:15:00 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:00 spla-repro volumio[19520]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 14:15:00 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 14:15:00 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:00 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:00 spla-repro volumio[19520]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 14:15:00 spla-repro volumio[19520]: info: MyVolumio login type: Token Aug 25 14:15:00 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:00 spla-repro go-librespot[19825]: go-librespot daemon starting... Aug 25 14:15:00 spla-repro volumio[19520]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 14:15:00 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 14:15:00 spla-repro go-librespot[19826]: time="2026-08-25T14:15:00+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:00 spla-repro go-librespot[19826]: time="2026-08-25T14:15:00+02:00" level=debug msg="app state loaded" Aug 25 14:15:00 spla-repro go-librespot[19826]: time="2026-08-25T14:15:00+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=info msg="zeroconf server listening on port 38805" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="obtained new client token: AAEqvznN5quzBoFJLixtefxKZ8WnEUezqQdLZqWjJrnpnnyXAwmkx0qUwHkZyGUMP2m7/vgdSmWz2wC7xyEVEEV77OUL2zPN08q7re0IEo/l4aF6jK1RlBxPQsjEJd9qQKcgM6cAJPSthnElMCl3MQcsWfn1xe/O6wUQagz5SFZ+jiS/fZ89YNw7wFCYFJIDP1GpLriG078J7AmcZoDS1y88uXsDB632xWLgg1vYuxrI319ctGF/Oo4=" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=debug msg="completed challenge" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:01 spla-repro go-librespot[19826]: time="2026-08-25T14:15:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:01 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:01 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:01 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 14:15:01 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 14:15:01 spla-repro volumio[19520]: info: Streaming services startup Aug 25 14:15:01 spla-repro volumio[19520]: info: Starting Streaming Daemon Aug 25 14:15:01 spla-repro sudo[19850]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:01 spla-repro volumio[19520]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 14:15:01 spla-repro sudo[19850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 14:15:01 spla-repro sudo[19850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:01 spla-repro sudo[19850]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:01 spla-repro volumio[19520]: info: Initializing connection to go-librespot Websocket Aug 25 14:15:01 spla-repro volumio[19520]: error: Cannot start Volumio Streaming Daemon Aug 25 14:15:01 spla-repro volumio[19520]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 14:15:01 spla-repro volumio[19520]: sudo: unable to resolve host spla-repro: System error Aug 25 14:15:01 spla-repro volumio[19520]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 14:15:01 spla-repro volumio[19520]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:15:01 spla-repro volumio[19520]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:01 spla-repro volumio[19520]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:01 spla-repro volumio[19520]: info: Listing playlists Aug 25 14:15:01 spla-repro volumio[19520]: info: Listing playlists Aug 25 14:15:02 spla-repro volumio[19520]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Aug 25 14:15:03 spla-repro volumio[19520]: info: MyVolumio token set successfully Aug 25 14:15:03 spla-repro volumio[19520]: info: MYVOLUMIO: Adding device Aug 25 14:15:03 spla-repro volumio[19520]: info: MYVOLUMIO: Evaluating Server Aug 25 14:15:03 spla-repro volumio[19520]: info: MyVolumio status changed Aug 25 14:15:03 spla-repro volumio[19520]: info: Streaming services startup Aug 25 14:15:03 spla-repro volumio[19520]: info: Starting Streaming Daemon Aug 25 14:15:03 spla-repro volumio[19520]: info: Removing browser output: myVolumio user plan is not superstar Aug 25 14:15:03 spla-repro volumio[19520]: info: Removing audio output: Aug 25 14:15:03 spla-repro volumio[19520]: info: Stoppping Tunnel 1 Aug 25 14:15:03 spla-repro sudo[19878]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:03 spla-repro sudo[19878]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 14:15:03 spla-repro sudo[19878]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:03 spla-repro sudo[19878]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:03 spla-repro sudo[19881]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:03 spla-repro volumio[19520]: error: Cannot start Volumio Streaming Daemon Aug 25 14:15:03 spla-repro volumio[19520]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 14:15:03 spla-repro volumio[19520]: sudo: unable to resolve host spla-repro: System error Aug 25 14:15:03 spla-repro volumio[19520]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 14:15:03 spla-repro sudo[19881]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Aug 25 14:15:03 spla-repro sudo[19881]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 14:15:03 spla-repro sudo[19881]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:03 spla-repro volumio[19520]: info: Remote SSH Stopped Aug 25 14:15:03 spla-repro volumio[19520]: info: Setting Geolocation for MyVolumio to eu6 Aug 25 14:15:03 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:03 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:03 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:04 spla-repro volumio[19520]: info: Successfully Added MyVolumio device Aug 25 14:15:04 spla-repro volumio[19520]: info: Updating MyVolumio device info Aug 25 14:15:04 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:04 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:04 spla-repro volumio[19520]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:04 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Aug 25 14:15:04 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:04 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:04 spla-repro go-librespot[19883]: go-librespot daemon starting... Aug 25 14:15:04 spla-repro go-librespot[19884]: time="2026-08-25T14:15:04+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:04 spla-repro go-librespot[19884]: time="2026-08-25T14:15:04+02:00" level=debug msg="app state loaded" Aug 25 14:15:04 spla-repro go-librespot[19884]: time="2026-08-25T14:15:04+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:04 spla-repro volumio[19520]: info: Initializing connection to go-librespot Websocket Aug 25 14:15:04 spla-repro go-librespot[19884]: time="2026-08-25T14:15:04+02:00" level=debug msg="new websocket client" Aug 25 14:15:04 spla-repro volumio[19520]: info: Connection to go-librespot Websocket established Aug 25 14:15:05 spla-repro volumio[19520]: info: Successfully Updated MyVolumio device Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=info msg="zeroconf server listening on port 34531" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="obtained new client token: AAG16ITKLjRunlDDCaH2g/017ZY+ts9MY4vnFZzJwQKDJKORV7qMzGPNMborHiGk885yE3qsznphFvIBfM1guvFsZ7UjRm4tLcRBQAHs0SjyO+k9h7xVdylEDUTOJwOMBwLKXxJwI/oPKY6T61GsZsFiNECnLzl1Qplj7gJ7WzHFoBehiWubWk2kpnaUeiKISgZJRmYQYnA17QF5tqrKy5+qpnhsUVd9vL18tv2g4IBbJ9h78ntfwFw=" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=debug msg="completed challenge" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:05 spla-repro go-librespot[19884]: time="2026-08-25T14:15:05+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:05 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:05 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:05 spla-repro volumio[19520]: info: Connection to go-librespot Websocket closed Aug 25 14:15:07 spla-repro volumio[19520]: info: Getting Spotify volume Aug 25 14:15:07 spla-repro volumio[19520]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:15:07 spla-repro volumio[19520]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:15:07 spla-repro volumio[19520]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 25 14:15:07 spla-repro volumio[19520]: errno: -111, Aug 25 14:15:07 spla-repro volumio[19520]: code: 'ECONNREFUSED', Aug 25 14:15:07 spla-repro volumio[19520]: syscall: 'connect', Aug 25 14:15:07 spla-repro volumio[19520]: address: '127.0.0.1', Aug 25 14:15:07 spla-repro volumio[19520]: port: 9879, Aug 25 14:15:07 spla-repro volumio[19520]: response: undefined Aug 25 14:15:07 spla-repro volumio[19520]: } Aug 25 14:15:07 spla-repro volumio[19520]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:15:08 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Aug 25 14:15:08 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:08 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:08 spla-repro go-librespot[19905]: go-librespot daemon starting... Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=debug msg="app state loaded" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:08 spla-repro sudo[19916]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:08 spla-repro sudo[19916]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 14:14' Aug 25 14:15:08 spla-repro sudo[19916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=info msg="zeroconf server listening on port 42431" Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:08 spla-repro sudo[19916]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:08 spla-repro volumio[19520]: sudo: unable to resolve host spla-repro: System error Aug 25 14:15:08 spla-repro go-librespot[19906]: time="2026-08-25T14:15:08+02:00" level=debug msg="obtained new client token: AAGVwA6T6AHkA//NqYCfPSSmOuse5+20JdKEb8FII2b3DqFIVFW7qmpuhJAEh1iy83w+3PZXVBQz9lggY878pbLohIiF6TaMuLo6TUvukB9qeVgXbuxMJdsR4JSQ8aHWYYMKOLRZ0gdw9AZ4dvakqiyHkjntxFnxQUu/47EoaS0nNCt3ivS/8YIMiNsnzf7lafMpDYGxWMkvfuIPgnAZM/HmNALNV/e2pIq3JqU1PeSLBZwaqsiN5JjjCw==" Aug 25 14:15:09 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:15:09.015+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Aug 25 14:15:09 spla-repro volumio-remote-updater[725]: [2026-08-25 14:15:09] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Aug 25 14:15:09 spla-repro volumio-remote-updater[725]: [2026-08-25 14:15:09] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Aug 25 14:15:09 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:09 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:15:09.020+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:15:09 spla-repro go-librespot[19906]: time="2026-08-25T14:15:09+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:09 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Aug 25 14:15:09 spla-repro systemd[1]: volumio.service: Consumed 27.988s CPU time. Aug 25 14:15:09 spla-repro go-librespot[19906]: time="2026-08-25T14:15:09+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:09 spla-repro go-librespot[19906]: time="2026-08-25T14:15:09+02:00" level=debug msg="completed challenge" Aug 25 14:15:09 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:15:09 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:15:09 spla-repro go-librespot[19906]: time="2026-08-25T14:15:09+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:09 spla-repro go-librespot[19906]: time="2026-08-25T14:15:09+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:09 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:09 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:09 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5438. Aug 25 14:15:09 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Aug 25 14:15:09 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Aug 25 14:15:09 spla-repro systemd[1]: volumio.service: Consumed 27.988s CPU time. Aug 25 14:15:09 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Aug 25 14:15:09 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Aug 25 14:15:10 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:15:10.022+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Aug 25 14:15:11 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:11 spla-repro volumio[19929]: info: ----- Volumio3 ---- Aug 25 14:15:11 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:11 spla-repro volumio[19929]: info: ----- System startup ---- Aug 25 14:15:11 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:12 spla-repro volumio[19929]: info: MYVOLUMIO Environment detected Aug 25 14:15:12 spla-repro volumio[19929]: info: Plugin folders cleanup Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning into folder /volumio/app/plugins/ Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category audio_interface Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category miscellanea Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category music_service Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category plugins.json Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category system_controller Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category user_interface Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning into folder /data/plugins/ Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category audio_interface Aug 25 14:15:12 spla-repro volumio[19929]: info: Scanning category music_service Aug 25 14:15:12 spla-repro volumio[19929]: info: Plugin folders cleanup completed Aug 25 14:15:12 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:12 spla-repro volumio[19929]: info: ----- Core plugins startup ---- Aug 25 14:15:12 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:12 spla-repro volumio[19929]: info: Loading plugins from folder /volumio/app/plugins/ Aug 25 14:15:12 spla-repro volumio[19929]: info: Adding plugin upnp to MyMusic Plugins Aug 25 14:15:12 spla-repro volumio[19929]: info: Adding plugin airplay_emulation to MyMusic Plugins Aug 25 14:15:12 spla-repro volumio[19929]: info: Adding plugin upnp_browser to MyMusic Plugins Aug 25 14:15:12 spla-repro volumio[19929]: info: Loading plugins from folder /data/plugins/ Aug 25 14:15:12 spla-repro volumio[19929]: info: Loading plugin "system"... Aug 25 14:15:12 spla-repro volumio[19929]: info: Loading plugin "appearance"... Aug 25 14:15:12 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Aug 25 14:15:12 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:12 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:12 spla-repro go-librespot[19956]: go-librespot daemon starting... Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=debug msg="app state loaded" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=info msg="zeroconf server listening on port 39975" Aug 25 14:15:12 spla-repro go-librespot[19957]: time="2026-08-25T14:15:12+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=debug msg="obtained new client token: AAGJ9iC/0vWnElpArLPRQF+0mvltfRwPvLbxs97e3iibRck04h5lFV3YDOUiDnB/x3W8Ai3mU4LNahGDJxTocFiMSxcuA2DtDuqQEUP7kfp+E7gJCDCWrLCS0EMAraD+06MGOBzAQZ+tujWik10oBYXuNogTdMj4Eam2DCZV+0DvRZhKUUU6uHBAhVfiskTSf4pzTCw/uXOrOgHn0DsjAQ6eHdi/yMHukP3tj2sfDcHb5NsRZ8g8n3AIyQ==" Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=debug msg="completed challenge" Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "network"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Refreshing Cached IP Addresses Aug 25 14:15:13 spla-repro sudo[19967]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:13 spla-repro sudo[19969]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:13 spla-repro sudo[19967]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:15:13 spla-repro sudo[19967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:13 spla-repro sudo[19969]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:15:13 spla-repro sudo[19969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:13 spla-repro sudo[19967]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "services"... Aug 25 14:15:13 spla-repro go-librespot[19957]: time="2026-08-25T14:15:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:13 spla-repro sudo[19976]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "volumio5onboarding"... Aug 25 14:15:13 spla-repro sudo[19969]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:13 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:13 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "alsa_controller"... Aug 25 14:15:13 spla-repro sudo[19976]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Aug 25 14:15:13 spla-repro sudo[19976]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:13 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "wizard"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "networkfs"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Starting Udev Watcher for removable devices Aug 25 14:15:13 spla-repro volumio[19929]: info: Ignoring mount for partition: boot Aug 25 14:15:13 spla-repro volumio[19929]: info: Ignoring mount for partition: volumio Aug 25 14:15:13 spla-repro volumio[19929]: info: Ignoring mount for partition: volumio_data Aug 25 14:15:13 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "volumio_command_line_client"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "upnp"... Aug 25 14:15:13 spla-repro volumio[19929]: info: [1787660113529] Starting Upmpd Daemon Aug 25 14:15:13 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "my_music"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "mpd"... Aug 25 14:15:13 spla-repro volumio[19929]: info: Loading plugin "upnp_browser"... Aug 25 14:15:14 spla-repro volumio-remote-updater[725]: [2026-08-25 14:15:14] [connect] Successful connection Aug 25 14:15:14 spla-repro sudo[19976]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:15 spla-repro volumio[19929]: info: Starting UPNP Browser Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "alarm-clock"... Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "airplay_emulation"... Aug 25 14:15:15 spla-repro volumio[19929]: info: Starting Shairport Sync Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "last_100"... Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "webradio"... Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "i2s_dacs"... Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "volumiodiscovery"... Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** For more information see Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:15:15 spla-repro volumio[19929]: *** WARNING *** For more information see Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** For more information see Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** Please fix your application to use the native API of Avahi! Aug 25 14:15:15 spla-repro node[19929]: *** WARNING *** For more information see Aug 25 14:15:15 spla-repro volumio[19929]: info: Applying required configuration parameters for plugin volumiodiscovery Aug 25 14:15:15 spla-repro volumio[19929]: info: Discovery: Started advertising with name: Spálňa-repro Aug 25 14:15:15 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 25 14:15:15 spla-repro volumio[19929]: info: Loading plugin "spop"... Aug 25 14:15:16 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Aug 25 14:15:16 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:16 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:16 spla-repro go-librespot[20003]: go-librespot daemon starting... Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=debug msg="app state loaded" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:16 spla-repro volumio[19929]: info: Loading plugin "outputs"... Aug 25 14:15:16 spla-repro volumio[19929]: info: Loading plugin "albumart"... Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=info msg="zeroconf server listening on port 45389" Aug 25 14:15:16 spla-repro go-librespot[20004]: time="2026-08-25T14:15:16+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:16 spla-repro volumio[19929]: info: Plugin example_plugin is not enabled Aug 25 14:15:16 spla-repro volumio[19929]: info: Loading plugin "inputs"... Aug 25 14:15:16 spla-repro volumio[19929]: info: Loading plugin "updater_comm"... Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=debug msg="obtained new client token: AAG+WYqTq84SSn7HfjllyDMeTRRrLoyB2F5tREw0ZKuNylSJrNp6wRldEEa8sPYQVnZ5OBpkq4FrsBi6H2ckFcoZby+DtToTRLvPcMa9O6ygPP9HuxNYil0hEfQ/8x1q59pW0jsPdXYyf+dipNPdUwmNz3h1ILX+3ki9PeKQ7vYOmjLxuHqs5fqdhYzMr71FjJM8+3hT+VQTHJlH+5/wqhKIrn35CIDP7/vDAvhLJ2n+gWqE524KORk=" Aug 25 14:15:17 spla-repro volumio[19929]: info: Plugin mpdemulation is not enabled Aug 25 14:15:17 spla-repro volumio[19929]: info: Loading plugin "rest_api"... Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:17 spla-repro volumio[19929]: info: Loading plugin "websocket"... Aug 25 14:15:17 spla-repro volumio[19929]: info: Starting Socket.io Server version 1.7.4 Aug 25 14:15:17 spla-repro volumio[19929]: info: Plugin fusiondsp is not enabled Aug 25 14:15:17 spla-repro volumio[19929]: info: Loading i18n strings for locale sk Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=debug msg="completed challenge" Aug 25 14:15:17 spla-repro volumio[19929]: Updating browse sources language Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::initPlayerControls Aug 25 14:15:17 spla-repro go-librespot[20004]: time="2026-08-25T14:15:17+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:15:17 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:17 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:17 spla-repro volumio[19929]: Express server listening on port 3000 Aug 25 14:15:17 spla-repro volumio[19929]: [Metrics] WebUI: 6s 538.47ms Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::resetVolumioState Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::getcurrentVolume Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:15:17 spla-repro volumio[19929]: info: Cannot read play queue from file Aug 25 14:15:17 spla-repro volumio[19929]: info: Volumio Network Manager: Network status updated: 1 Aug 25 14:15:17 spla-repro volumio[19929]: Unable to parse: Aug 25 14:15:17 spla-repro volumio[19929]: Simple mixer control 'Master',0 Aug 25 14:15:17 spla-repro volumio[19929]: Capabilities: volume volume-joined Aug 25 14:15:17 spla-repro volumio[19929]: Playback channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Capture channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Limits: 0 - 248 Aug 25 14:15:17 spla-repro volumio[19929]: Mono: 112 [45%] Aug 25 14:15:17 spla-repro volumio[19929]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:15:17 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Aug 25 14:15:17 spla-repro volumio[20013]: Forking 3 albumart workers Aug 25 14:15:17 spla-repro volumio[19929]: 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 25 14:15:17 spla-repro volumio[19929]: Unable to parse: Aug 25 14:15:17 spla-repro volumio[19929]: Simple mixer control 'Master',0 Aug 25 14:15:17 spla-repro volumio[19929]: Capabilities: volume volume-joined Aug 25 14:15:17 spla-repro volumio[19929]: Playback channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Capture channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Limits: 0 - 248 Aug 25 14:15:17 spla-repro volumio[19929]: Mono: 112 [45%] Aug 25 14:15:17 spla-repro volumio[19929]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::pushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioPushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::updateTrackBlock Aug 25 14:15:17 spla-repro volumio[19929]: info: CorePlayQueue::getTrackBlock Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioRetrievevolume Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:17 spla-repro volumio[19929]: 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 25 14:15:17 spla-repro volumio[19929]: info: Setting Device type: Raspberry PI Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::setRepeat null single undefined Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::pushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioPushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::setRandom null Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::pushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioPushState Aug 25 14:15:17 spla-repro volumio-remote-updater[725]: [2026-08-25 14:15:17] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1787660114 101 Aug 25 14:15:17 spla-repro volumio[19929]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Aug 25 14:15:17 spla-repro volumio[19929]: info: Completed loading Core Plugins Aug 25 14:15:17 spla-repro volumio[19929]: info: Preparing to generate the ALSA configuration file Aug 25 14:15:17 spla-repro volumio[19929]: Unable to parse: Aug 25 14:15:17 spla-repro volumio[19929]: Simple mixer control 'Master',0 Aug 25 14:15:17 spla-repro volumio[19929]: Capabilities: volume volume-joined Aug 25 14:15:17 spla-repro volumio[19929]: Playback channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Capture channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Limits: 0 - 248 Aug 25 14:15:17 spla-repro volumio[19929]: Mono: 112 [45%] Aug 25 14:15:17 spla-repro volumio[19929]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Aug 25 14:15:17 spla-repro volumio[19929]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: Found device kuchyna-repro Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: Connecting to remote: 192.168.200.201 Aug 25 14:15:17 spla-repro volumio[19929]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 25 14:15:17 spla-repro volumio[19929]: Unable to parse: Aug 25 14:15:17 spla-repro volumio[19929]: Simple mixer control 'Master',0 Aug 25 14:15:17 spla-repro volumio[19929]: Capabilities: volume volume-joined Aug 25 14:15:17 spla-repro volumio[19929]: Playback channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Capture channels: Mono Aug 25 14:15:17 spla-repro volumio[19929]: Limits: 0 - 248 Aug 25 14:15:17 spla-repro volumio[19929]: Mono: 112 [45%] Aug 25 14:15:17 spla-repro volumio[19929]: info: VolumeController:: Volume=undefined Mute =false Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreStateMachine::pushState Aug 25 14:15:17 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:17 spla-repro volumio[19929]: info: CoreCommandRouter::volumioPushState Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: Found device kupelna-repro Aug 25 14:15:17 spla-repro volumio[19929]: info: Discovery: Connecting to remote: 192.168.200.202 Aug 25 14:15:17 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 6 Aug 25 14:15:18 spla-repro volumio[19929]: info: Asound.conf file unchanged, so no further update is needed Aug 25 14:15:18 spla-repro volumio[19929]: info: Output device has changed, restarting MPD Aug 25 14:15:18 spla-repro volumio[19929]: info: Output device has changed, restarting Shairport Sync Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:18 spla-repro sudo[20072]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro sudo[20071]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro sudo[20072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:15:18 spla-repro sudo[20072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:18 spla-repro sudo[20071]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:15:18 spla-repro sudo[20071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:18 spla-repro volumio[19929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:15:18 spla-repro volumio[19929]: info: ___________ START PLUGINS ___________ Aug 25 14:15:18 spla-repro sudo[20071]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:18 spla-repro volumio[19929]: info: ControllerMpd::onStart: Initializing MPD Aug 25 14:15:18 spla-repro volumio[19929]: info: Creating MPD Configuration file Aug 25 14:15:18 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:15:18 spla-repro volumio[19929]: info: [1787660118163] CoreMusicLibrary::Adding element Mediálne servery Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:15:18 spla-repro volumio[19929]: info: UPNP Browser: Client initialized successfully Aug 25 14:15:18 spla-repro sudo[20084]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:15:18 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:15:18 spla-repro systemd[1]: mpd.service: Consumed 3.998s CPU time. Aug 25 14:15:18 spla-repro sudo[20080]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:15:18 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:15:18 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:15:18 spla-repro sudo[20084]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 25 14:15:18 spla-repro sudo[20084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:18 spla-repro sudo[20082]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro sudo[20082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 25 14:15:18 spla-repro sudo[20082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:18 spla-repro sudo[20080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Aug 25 14:15:18 spla-repro sudo[20080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:18 spla-repro sudo[20082]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:18 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:15:18 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:15:18 spla-repro volumio[19929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:15:18 spla-repro volumio[19929]: info: [1787660118369] CoreMusicLibrary::Adding element Last_100 Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:15:18 spla-repro volumio[19929]: info: [1787660118388] CoreMusicLibrary::Adding element Webradio Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:15:18 spla-repro systemd[1]: mpd.service: Deactivated successfully. Aug 25 14:15:18 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 25 14:15:18 spla-repro volumio[19929]: info: Initializing BBC Radios Aug 25 14:15:18 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Aug 25 14:15:18 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 25 14:15:18 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 25 14:15:18 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 25 14:15:18 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Aug 25 14:15:18 spla-repro sudo[20080]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:18 spla-repro volumio[19929]: info: Creating Spotify config file Aug 25 14:15:18 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:18 spla-repro sudo[20103]: root : unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro sudo[20103]: sudo: unable to resolve host spla-repro: System error Aug 25 14:15:18 spla-repro sudo[20103]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 25 14:15:18 spla-repro sudo[20103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 25 14:15:18 spla-repro sudo[20103]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:19 spla-repro volumio[19929]: info: Volumio Calling Home Aug 25 14:15:19 spla-repro volumio[20032]: Starting albumart workers Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:19 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:19 spla-repro volumio[20030]: Starting albumart workers Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: Found device Spálňa-repro Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:19 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: Found device Spálňa-repro Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:19 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:19 spla-repro volumio[20031]: Starting albumart workers Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: Connected to remote: 192.168.200.201 Aug 25 14:15:19 spla-repro volumio[19929]: info: MPD Permissions set Aug 25 14:15:19 spla-repro volumio[19929]: info: MPD Permissions set Aug 25 14:15:19 spla-repro volumio[19929]: info: Discovery: Connected to remote: 192.168.200.202 Aug 25 14:15:19 spla-repro volumio[19929]: info: Volumio called home Aug 25 14:15:19 spla-repro volumio[19929]: info: Spotify config file written Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Aug 25 14:15:19 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:19 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:19 spla-repro sudo[20119]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:19 spla-repro sudo[20119]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 25 14:15:19 spla-repro sudo[20119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:20 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:20 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:20 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 6 Aug 25 14:15:20 spla-repro go-librespot[20121]: go-librespot daemon starting... Aug 25 14:15:20 spla-repro sudo[20119]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="app state loaded" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 14:15:20 spla-repro volumio[19929]: info: No need to fix Spotify hosts Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=info msg="zeroconf server listening on port 32963" Aug 25 14:15:20 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:20 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="obtained new client token: AAFMIS/W7KADbu3M0CBGZn2YvVwMDCSHC+ZL7jJSI3uDPPClJY3WdD7vDJ/4DqWiwiubGZ2n6VNvHLmcjjauADcLYaIR5ZqNq2OSizsHjYs0KzZIUQpYRujdCyiWP4ZU+TohBtLbZuCc5QIFbnGOJJEgEjIVrYs/RkCIHeHZtph6odNJEsWJ7VtLMZLO2PWLYBwb0zeOt7aXFvAinp/Tikuu3uCM6mwj6G3ivjK7SMNaF8ZoZTYNOG1bIA==" Aug 25 14:15:20 spla-repro volumio[19929]: info: New Spotify access tokenBQBSMrQ0C9... Aug 25 14:15:20 spla-repro volumio[19929]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 25 14:15:20 spla-repro volumio[19929]: info: Starting Shairport Sync Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 14:15:20 spla-repro volumio[19929]: info: Starting Shairport Sync Aug 25 14:15:20 spla-repro volumio[19929]: info: Starting Shairport Sync Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=debug msg="completed challenge" Aug 25 14:15:20 spla-repro sudo[20148]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:20 spla-repro sudo[20148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:15:20 spla-repro sudo[20148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:20 spla-repro go-librespot[20122]: time="2026-08-25T14:15:20+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:20 spla-repro sudo[20156]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:20 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:20 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:20 spla-repro sudo[20156]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:15:20 spla-repro sudo[20156]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:21 spla-repro sudo[20159]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:21 spla-repro sudo[20159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 25 14:15:21 spla-repro sudo[20159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 14:15:21 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 14:15:21 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:15:21 spla-repro systemd[1]: shairport-sync.service: Consumed 1.864s CPU time. Aug 25 14:15:21 spla-repro volumio[19929]: info: Listing playlists Aug 25 14:15:21 spla-repro volumio[19929]: info: Listing playlists Aug 25 14:15:21 spla-repro go-librespot[20122]: time="2026-08-25T14:15:21+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:15:21 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:21 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:21 spla-repro sudo[20148]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:21 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 25 14:15:21 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Aug 25 14:15:21 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:15:21 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 25 14:15:21 spla-repro sudo[20156]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:21 spla-repro volumio[19929]: info: Shairport-Sync Started Aug 25 14:15:21 spla-repro sudo[20159]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:21 spla-repro volumio[19929]: Error adding Membership: Error: addMembership EINVAL Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro volumio[19929]: info: Shairport-Sync Started Aug 25 14:15:21 spla-repro volumio[19929]: info: Shairport-Sync Started Aug 25 14:15:21 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:21 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 7 Aug 25 14:15:21 spla-repro volumio[19929]: SPOTIFY: User informations: {"account_id":"KCva7ZO5Mg","country":"SK","display_name":"Slavomír Predajnoš","email":"slavomir.predajnos@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/4bvaalzmfnjdythud03i86slb"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/4bvaalzmfnjdythud03i86slb","id":"4bvaalzmfnjdythud03i86slb","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85850b6099547eb40fb8c3b7c6","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82850b6099547eb40fb8c3b7c6","width":64}],"product":"premium","type":"user","uri":"spotify:user:4bvaalzmfnjdythud03i86slb"} Aug 25 14:15:21 spla-repro volumio[19929]: info: Spotify Successfully logged in Aug 25 14:15:21 spla-repro volumio[19929]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 25 14:15:21 spla-repro volumio[19929]: info: [1787660121436] CoreMusicLibrary::Adding element Spotify Aug 25 14:15:21 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 14:15:21 spla-repro volumio[19929]: Cannot find translation for source Spotify Aug 25 14:15:22 spla-repro mpd[20114]: 2026-08-25T14:15:22 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 25 14:15:22 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Aug 25 14:15:22 spla-repro sudo[20084]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:22 spla-repro sudo[20072]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:22 spla-repro volumio[19929]: info: Completed starting Core Plugins Aug 25 14:15:22 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:22 spla-repro volumio[19929]: info: ----- MyVolumio plugins startup ---- Aug 25 14:15:22 spla-repro volumio[19929]: info: ------------------------------------------- Aug 25 14:15:22 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Fetching plans data.... Aug 25 14:15:22 spla-repro volumio[19929]: error: MPD error: The expression evaluated to a falsy value: Aug 25 14:15:22 spla-repro volumio[19929]: assert.ok(self.idling) Aug 25 14:15:22 spla-repro volumio[19929]: error: The expression evaluated to a falsy value: Aug 25 14:15:22 spla-repro volumio[19929]: assert.ok(self.idling) Aug 25 14:15:22 spla-repro volumio[19929]: info: MPD running with PID20114 Aug 25 14:15:22 spla-repro volumio[19929]: ,establishing connection Aug 25 14:15:22 spla-repro volumio[19929]: error: updateQueue error: null Aug 25 14:15:22 spla-repro volumio[19929]: error: updateQueue error: null Aug 25 14:15:23 spla-repro sudo[20203]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:23 spla-repro sudo[20205]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:23 spla-repro sudo[20203]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 14:15:23 spla-repro sudo[20203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:23 spla-repro sudo[20203]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:23 spla-repro sudo[20205]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 14:15:23 spla-repro sudo[20205]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:23 spla-repro sudo[20205]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:23 spla-repro sudo[20208]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:23 spla-repro sudo[20208]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Aug 25 14:15:23 spla-repro sudo[20208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:23 spla-repro volumio[19929]: info: go-librespot daemon successfully initialized Aug 25 14:15:23 spla-repro sudo[20208]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:23 spla-repro volumio[19929]: info: Upmpdcli Daemon Started Aug 25 14:15:24 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Aug 25 14:15:24 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:24 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:24 spla-repro go-librespot[20211]: go-librespot daemon starting... Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="app state loaded" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:24 spla-repro volumio5-onboarding[16326]: time=2026-08-25T14:15:24.486+02:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=info msg="zeroconf server listening on port 37305" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="obtained new client token: AAGWVvpruZyhXaYUSV2jyeAcJAoF54A2uPRoFnbit5hm20K7/OsfCfpVyg7yFsbWilHq1bft6WzWe1SFO7vjx4BMAqzRoct/wA+56PulIgp9XXUQ23j3L8czYy/+eehT7/cqz0SBEK6Vn3+rRZGbcreR1D2We/sMR6qCAjuoNCbdFM0CQWvUMHX1O6T+N/6ZQeaXvQDRcxmIPCR+RAXj20rdT1gk6eQacXnaZKIEAgEO6sPgFSo06BsnqA==" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=debug msg="completed challenge" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:24 spla-repro go-librespot[20212]: time="2026-08-25T14:15:24+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:24 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:24 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:26 spla-repro volumio[19929]: info: Initializing connection to go-librespot Websocket Aug 25 14:15:26 spla-repro volumio[19929]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:15:27 spla-repro volumio[19929]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Aug 25 14:15:27 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Aug 25 14:15:27 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:28 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:28 spla-repro go-librespot[20221]: go-librespot daemon starting... Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=debug msg="app state loaded" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15: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-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=info msg="zeroconf server listening on port 37203" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=debug msg="obtained new client token: AAE1hDfg7h8fyYFxdutVlqk04FW8Z8WhW1HaNGxlMHGxbC6zpvLHW/sW9YsRKLikuxVMxXZkN7k3lEypzcGygECc5OC7chvh863gyQTeEgjR+KlKDXJjuSZ3C0E4sWosczii7J8fbmr0zYIcd+yzNs/HkL6PhfJkUOoi/uQ+5vpnL66DLhtz1cXQ/AIXG/ZQXzjRVa5MIMiZC5BeDw0uE5C7ODU3pna0Sx/tFF0pMkrVWxIEbLPWbL086g==" Aug 25 14:15:28 spla-repro go-librespot[20222]: time="2026-08-25T14:15:28+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Aug 25 14:15:29 spla-repro go-librespot[20222]: time="2026-08-25T14:15:29+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:29 spla-repro go-librespot[20222]: time="2026-08-25T14:15:29+02:00" level=debug msg="completed challenge" Aug 25 14:15:29 spla-repro volumio[19929]: info: Initializing connection to go-librespot Websocket Aug 25 14:15:29 spla-repro go-librespot[20222]: time="2026-08-25T14:15:29+02:00" level=debug msg="new websocket client" Aug 25 14:15:29 spla-repro volumio[19929]: info: Connection to go-librespot Websocket established Aug 25 14:15:29 spla-repro go-librespot[20222]: time="2026-08-25T14:15:29+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:29 spla-repro go-librespot[20222]: time="2026-08-25T14:15:29+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:29 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:29 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:29 spla-repro volumio[19929]: info: Connection to go-librespot Websocket closed Aug 25 14:15:30 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:30 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin bluetooth to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin multiroom to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin metavolumio to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin cd_controller to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin qobuzconnect to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin smart_inputs to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: Adding plugin tidalconnect to MyMusic Plugins Aug 25 14:15:31 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Aug 25 14:15:32 spla-repro volumio[19929]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Aug 25 14:15:32 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Aug 25 14:15:32 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:32 spla-repro volumio[19929]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 14:15:32 spla-repro volumio[19929]: info: Starting MyVolumio Remote Streaming Endpoints Aug 25 14:15:32 spla-repro volumio[19929]: info: MyVolumio login type: Token Aug 25 14:15:32 spla-repro volumio[19929]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Aug 25 14:15:32 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Aug 25 14:15:32 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Aug 25 14:15:32 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:32 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 14:15:32 spla-repro go-librespot[20231]: go-librespot daemon starting... Aug 25 14:15:32 spla-repro go-librespot[20232]: time="2026-08-25T14:15:32+02:00" level=info msg="running go-librespot 0.7.1" Aug 25 14:15:32 spla-repro go-librespot[20232]: time="2026-08-25T14:15:32+02:00" level=debug msg="app state loaded" Aug 25 14:15:32 spla-repro go-librespot[20232]: time="2026-08-25T14:15:32+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 14:15:33 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Aug 25 14:15:33 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Aug 25 14:15:33 spla-repro volumio[19929]: info: Streaming services startup Aug 25 14:15:33 spla-repro volumio[19929]: info: Starting Streaming Daemon Aug 25 14:15:33 spla-repro sudo[20241]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:33 spla-repro sudo[20241]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Aug 25 14:15:33 spla-repro sudo[20241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 14:15:33 spla-repro volumio[19929]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Aug 25 14:15:33 spla-repro sudo[20241]: pam_unix(sudo:session): session closed for user root Aug 25 14:15:33 spla-repro volumio[19929]: info: Getting Spotify volume Aug 25 14:15:33 spla-repro volumio[19929]: info: Initializing connection to go-librespot Websocket Aug 25 14:15:33 spla-repro volumio[19929]: error: Cannot start Volumio Streaming Daemon Aug 25 14:15:33 spla-repro volumio[19929]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Aug 25 14:15:33 spla-repro volumio[19929]: sudo: unable to resolve host spla-repro: System error Aug 25 14:15:33 spla-repro volumio[19929]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="new websocket client" Aug 25 14:15:33 spla-repro volumio[19929]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 25 14:15:33 spla-repro volumio[19929]: info: Connection to go-librespot Websocket established Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=info msg="zeroconf server listening on port 37015" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 25 14:15:33 spla-repro volumio[19929]: info: CoreCommandRouter::volumioGetState Aug 25 14:15:33 spla-repro volumio[19929]: info: CorePlayQueue::getTrack 0 Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="obtained new client token: AAGH9lyBJ2yA4oXja1RaMjCbTc/DO8MZnjkczTQ+wVwlbvwywxh4qVb2Gh94CV7K8ZnurfUA++yBFJwkTHAMqob8J6Rlrpi2XyDVh1uE8gXUvmGZWWVMqEMt/glsDpjea0h6w29bkw39jItXwHWWxteUoIwEfNrxJ9w4Mn15wgByYfVOG1ddQ3BXCPdlOjX3bDvgyySD9a9tA/Gw0SzIoMbg+5KZLZs7VsT5eU3Y5HaHFHesAFOe40CfHw==" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="completed keyexchange" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=debug msg="completed challenge" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=info msg="authenticated AP" username="4b*********************lb" Aug 25 14:15:33 spla-repro go-librespot[20232]: time="2026-08-25T14:15:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 14:15:33 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:15:33 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:15:33 spla-repro volumio[19929]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:15:33 spla-repro volumio[19929]: Error: socket hang up Aug 25 14:15:33 spla-repro volumio[19929]: at connResetException (node:internal/errors:720:14) Aug 25 14:15:33 spla-repro volumio[19929]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 25 14:15:33 spla-repro volumio[19929]: at Socket.emit (node:events:526:35) Aug 25 14:15:33 spla-repro volumio[19929]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 25 14:15:33 spla-repro volumio[19929]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 25 14:15:33 spla-repro volumio[19929]: code: 'ECONNRESET', Aug 25 14:15:33 spla-repro volumio[19929]: response: undefined Aug 25 14:15:33 spla-repro volumio[19929]: } Aug 25 14:15:33 spla-repro volumio[19929]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 14:15:34 spla-repro sudo[20276]: volumio : unable to resolve host spla-repro: System error Aug 25 14:15:34 spla-repro sudo[20276]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 14:14' Aug 25 14:15:34 spla-repro sudo[20276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="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"