Sep 01 01:53:00 spla-repro volumio[28001]: info: Updating MyVolumio device info Sep 01 01:53:00 spla-repro volumio[28001]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:00 spla-repro volumio[28001]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:00 spla-repro volumio[28001]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:00 spla-repro volumio[28001]: info: Successfully Updated MyVolumio device Sep 01 01:53:02 spla-repro volumio[28001]: info: Getting Spotify volume Sep 01 01:53:02 spla-repro volumio[28001]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:53:02 spla-repro volumio[28001]: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:02 spla-repro volumio[28001]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Sep 01 01:53:02 spla-repro volumio[28001]: errno: -111, Sep 01 01:53:02 spla-repro volumio[28001]: code: 'ECONNREFUSED', Sep 01 01:53:02 spla-repro volumio[28001]: syscall: 'connect', Sep 01 01:53:02 spla-repro volumio[28001]: address: '127.0.0.1', Sep 01 01:53:02 spla-repro volumio[28001]: port: 9879, Sep 01 01:53:02 spla-repro volumio[28001]: response: undefined Sep 01 01:53:02 spla-repro volumio[28001]: } Sep 01 01:53:02 spla-repro volumio[28001]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:53:02 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Sep 01 01:53:02 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:02 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:02 spla-repro go-librespot[28400]: go-librespot daemon starting... Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=debug msg="app state loaded" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+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]" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+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]" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=info msg="zeroconf server listening on port 36519" Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:02 spla-repro sudo[28412]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:02 spla-repro sudo[28412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-01 01:52' Sep 01 01:53:02 spla-repro sudo[28412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:02 spla-repro go-librespot[28401]: time="2026-09-01T01:53:02+02:00" level=debug msg="obtained new client token: AAFIxPzjygJC7WWYfV4od3N6h9AJAB83IvAl6c0cT9pJ2gFnEcVkR6VrcW7pH6WOnymgyJFyIr/mEzVFGk5/MwFiHXR9kFriMCEhjF5BZ1a7tQOZMutiSLoqEphiO1/DWURc1UntY6oA7QlGibmtV55/ZREh/D9ykyJEMpoYvbvUdV2AonHr69UgcQxr5NTM3rNKIzkUOU6OKZL8qVO00leN1gBiM8k7jJtJz8zPKF6ZOoIsPqHbaO1d3Q==" Sep 01 01:53:03 spla-repro go-librespot[28401]: time="2026-09-01T01:53:03+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:03 spla-repro go-librespot[28401]: time="2026-09-01T01:53:03+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:03 spla-repro go-librespot[28401]: time="2026-09-01T01:53:03+02:00" level=debug msg="completed challenge" Sep 01 01:53:03 spla-repro sudo[28412]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:03 spla-repro go-librespot[28401]: time="2026-09-01T01:53:03+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:03 spla-repro go-librespot[28401]: time="2026-09-01T01:53:03+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:03 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:03 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:03 spla-repro volumio[28001]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:03 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:03] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Sep 01 01:53:03 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:03] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Sep 01 01:53:03 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:03.445+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Sep 01 01:53:03 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:03 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:03.447+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:53:03 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Sep 01 01:53:03 spla-repro systemd[1]: volumio.service: Consumed 27.758s CPU time. Sep 01 01:53:03 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:53:03 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:53:03 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 15808. Sep 01 01:53:03 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:53:03 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Sep 01 01:53:03 spla-repro systemd[1]: volumio.service: Consumed 27.758s CPU time. Sep 01 01:53:03 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Sep 01 01:53:03 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:53:04 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:04.449+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:53:05 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:05 spla-repro volumio[28431]: info: ----- Volumio3 ---- Sep 01 01:53:05 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:05 spla-repro volumio[28431]: info: ----- System startup ---- Sep 01 01:53:05 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:06 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Sep 01 01:53:06 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:06 spla-repro volumio[28431]: info: MYVOLUMIO Environment detected Sep 01 01:53:06 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:06 spla-repro go-librespot[28453]: go-librespot daemon starting... Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=debug msg="app state loaded" Sep 01 01:53:06 spla-repro volumio[28431]: info: Plugin folders cleanup Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning into folder /volumio/app/plugins/ Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category audio_interface Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category miscellanea Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category music_service Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category plugins.json Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category system_controller Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category user_interface Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning into folder /data/plugins/ Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category audio_interface Sep 01 01:53:06 spla-repro volumio[28431]: info: Scanning category music_service Sep 01 01:53:06 spla-repro volumio[28431]: info: Plugin folders cleanup completed Sep 01 01:53:06 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:06 spla-repro volumio[28431]: info: ----- Core plugins startup ---- Sep 01 01:53:06 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:06 spla-repro volumio[28431]: info: Loading plugins from folder /volumio/app/plugins/ Sep 01 01:53:06 spla-repro volumio[28431]: info: Adding plugin upnp to MyMusic Plugins Sep 01 01:53:06 spla-repro volumio[28431]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 01 01:53:06 spla-repro volumio[28431]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 01 01:53:06 spla-repro volumio[28431]: info: Loading plugins from folder /data/plugins/ Sep 01 01:53:06 spla-repro volumio[28431]: info: Loading plugin "system"... Sep 01 01:53:06 spla-repro volumio[28431]: info: Loading plugin "appearance"... Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=info msg="zeroconf server listening on port 37715" Sep 01 01:53:06 spla-repro go-librespot[28457]: time="2026-09-01T01:53:06+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=debug msg="obtained new client token: AAETlYcmWSff1EW5d6UsjlX1x/bgGUbhN1lL27dYbUnFk32fTV6XEuUx+KtA+O760Z02a2m5476DfLBNABvvXYIAwvxSseVYas7TOUcQDUQ5zuzRNwRasIMmfT7uZ0KOlpOr6GZ6OMi0YTdPBooVY8Am74lQEdFwMi3Eot9fQjdWHo/dDBJagUCSCnwaY1tq5x0GIantBje25KutW9cLSp+r0awKSGziHswvXYGd12XgBBLT2SqIRwMimQ==" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=debug msg="completed challenge" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:07 spla-repro go-librespot[28457]: time="2026-09-01T01:53:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:07 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:07 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "network"... Sep 01 01:53:07 spla-repro volumio[28431]: info: Refreshing Cached IP Addresses Sep 01 01:53:07 spla-repro sudo[28471]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:07 spla-repro sudo[28473]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:07 spla-repro sudo[28473]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:53:07 spla-repro sudo[28473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:07 spla-repro sudo[28471]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "services"... Sep 01 01:53:07 spla-repro sudo[28473]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:07 spla-repro sudo[28471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "volumio5onboarding"... Sep 01 01:53:07 spla-repro sudo[28471]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:07 spla-repro sudo[28479]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:07 spla-repro sudo[28479]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "alsa_controller"... Sep 01 01:53:07 spla-repro sudo[28479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:07 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "wizard"... Sep 01 01:53:07 spla-repro volumio[28431]: info: Loading plugin "networkfs"... Sep 01 01:53:08 spla-repro volumio[28431]: info: Starting Udev Watcher for removable devices Sep 01 01:53:08 spla-repro volumio[28431]: info: Ignoring mount for partition: boot Sep 01 01:53:08 spla-repro volumio[28431]: info: Ignoring mount for partition: volumio Sep 01 01:53:08 spla-repro volumio[28431]: info: Ignoring mount for partition: volumio_data Sep 01 01:53:08 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:08 spla-repro volumio[28431]: info: Loading plugin "volumio_command_line_client"... Sep 01 01:53:08 spla-repro volumio[28431]: info: Loading plugin "upnp"... Sep 01 01:53:08 spla-repro volumio[28431]: info: [1788220388049] Starting Upmpd Daemon Sep 01 01:53:08 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:08 spla-repro volumio[28431]: info: Loading plugin "my_music"... Sep 01 01:53:08 spla-repro volumio[28431]: info: Loading plugin "mpd"... Sep 01 01:53:08 spla-repro volumio[28431]: info: Loading plugin "upnp_browser"... Sep 01 01:53:08 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:08] [connect] Successful connection Sep 01 01:53:08 spla-repro sudo[28479]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:09 spla-repro volumio[28431]: info: Starting UPNP Browser Sep 01 01:53:09 spla-repro volumio[28431]: info: Loading plugin "alarm-clock"... Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "airplay_emulation"... Sep 01 01:53:10 spla-repro volumio[28431]: info: Starting Shairport Sync Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "last_100"... Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "webradio"... Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "i2s_dacs"... Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "volumiodiscovery"... Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** For more information see Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:10 spla-repro volumio[28431]: *** WARNING *** For more information see Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** For more information see Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:10 spla-repro node[28431]: *** WARNING *** For more information see Sep 01 01:53:10 spla-repro volumio[28431]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 01 01:53:10 spla-repro volumio[28431]: info: Discovery: Started advertising with name: Spálňa-repro Sep 01 01:53:10 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:10 spla-repro volumio[28431]: info: Loading plugin "spop"... Sep 01 01:53:10 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Sep 01 01:53:10 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:10 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:10 spla-repro go-librespot[28506]: go-librespot daemon starting... Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=debug msg="app state loaded" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+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]" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+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]" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=info msg="zeroconf server listening on port 46583" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:10 spla-repro go-librespot[28507]: time="2026-09-01T01:53:10+02:00" level=debug msg="obtained new client token: AAFuT+GMk4cR3CoscS5D39+BJJHNni3p/jZKp+6RhZO+bKCYPrvlIcbB7S/TY8jIf1KMWCXbdzGQ0JnAzO4i8yJrWk+O5DNVSKshchMF/445+CJIWk0SU0ywaw1ViaCJWeTgnYoBK6qHozXaxOfZEmTG+yiPEbH89a//VzMDZgXQAhXxGde9AUviLs+dqH0dM/Er3BbSVEmdU1JIkGEVQlhdhCoHEaYoulUk+rCC22XK6V1UHVHCFjS60Q==" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="completed challenge" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "outputs"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "albumart"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Plugin example_plugin is not enabled Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "inputs"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "updater_comm"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Plugin mpdemulation is not enabled Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "rest_api"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading plugin "websocket"... Sep 01 01:53:11 spla-repro volumio[28431]: info: Starting Socket.io Server version 1.7.4 Sep 01 01:53:11 spla-repro volumio[28431]: info: Plugin fusiondsp is not enabled Sep 01 01:53:11 spla-repro volumio[28431]: info: Loading i18n strings for locale sk Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Sep 01 01:53:11 spla-repro volumio[28431]: Updating browse sources language Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=debug msg="completed challenge" Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::initPlayerControls Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:11 spla-repro volumio[28431]: Express server listening on port 3000 Sep 01 01:53:11 spla-repro volumio[28431]: [Metrics] WebUI: 6s 585.22ms Sep 01 01:53:11 spla-repro go-librespot[28507]: time="2026-09-01T01:53:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreStateMachine::resetVolumioState Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreStateMachine::getcurrentVolume Sep 01 01:53:11 spla-repro volumio[28431]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:53:11 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:11 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:11 spla-repro volumio[28431]: info: Cannot read play queue from file Sep 01 01:53:11 spla-repro volumio[28431]: info: Volumio Network Manager: Network status updated: 1 Sep 01 01:53:12 spla-repro volumio[28431]: 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 Sep 01 01:53:12 spla-repro volumio[28431]: Unable to parse: Sep 01 01:53:12 spla-repro volumio[28431]: Simple mixer control 'Master',0 Sep 01 01:53:12 spla-repro volumio[28431]: Capabilities: volume volume-joined Sep 01 01:53:12 spla-repro volumio[28431]: Playback channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Capture channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Limits: 0 - 248 Sep 01 01:53:12 spla-repro volumio[28431]: Mono: 112 [45%] Sep 01 01:53:12 spla-repro volumio[28431]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:53:12 spla-repro volumio[28516]: Forking 3 albumart workers Sep 01 01:53:12 spla-repro volumio[28431]: 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 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: 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 Sep 01 01:53:12 spla-repro volumio[28431]: Unable to parse: Sep 01 01:53:12 spla-repro volumio[28431]: Simple mixer control 'Master',0 Sep 01 01:53:12 spla-repro volumio[28431]: Capabilities: volume volume-joined Sep 01 01:53:12 spla-repro volumio[28431]: Playback channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Capture channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Limits: 0 - 248 Sep 01 01:53:12 spla-repro volumio[28431]: Mono: 112 [45%] Sep 01 01:53:12 spla-repro volumio[28431]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::pushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::updateTrackBlock Sep 01 01:53:12 spla-repro volumio[28431]: info: CorePlayQueue::getTrackBlock Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::setRepeat null single undefined Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::pushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::setRandom null Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::pushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:12 spla-repro volumio[28431]: info: Setting Device type: Raspberry PI Sep 01 01:53:12 spla-repro volumio[28431]: 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 Sep 01 01:53:12 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788220388 101 Sep 01 01:53:12 spla-repro volumio[28431]: info: Completed loading Core Plugins Sep 01 01:53:12 spla-repro volumio[28431]: info: Preparing to generate the ALSA configuration file Sep 01 01:53:12 spla-repro volumio[28431]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Sep 01 01:53:12 spla-repro volumio[28431]: Unable to parse: Sep 01 01:53:12 spla-repro volumio[28431]: Simple mixer control 'Master',0 Sep 01 01:53:12 spla-repro volumio[28431]: Capabilities: volume volume-joined Sep 01 01:53:12 spla-repro volumio[28431]: Playback channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Capture channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Limits: 0 - 248 Sep 01 01:53:12 spla-repro volumio[28431]: Mono: 112 [45%] Sep 01 01:53:12 spla-repro volumio[28431]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: Found device kuchyna-repro Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: Connecting to remote: 192.168.200.201 Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: Found device kupelna-repro Sep 01 01:53:12 spla-repro volumio[28431]: info: Discovery: Connecting to remote: 192.168.200.202 Sep 01 01:53:12 spla-repro volumio[28431]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Sep 01 01:53:12 spla-repro volumio[28431]: 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 Sep 01 01:53:12 spla-repro volumio[28431]: Unable to parse: Sep 01 01:53:12 spla-repro volumio[28431]: Simple mixer control 'Master',0 Sep 01 01:53:12 spla-repro volumio[28431]: Capabilities: volume volume-joined Sep 01 01:53:12 spla-repro volumio[28431]: Playback channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Capture channels: Mono Sep 01 01:53:12 spla-repro volumio[28431]: Limits: 0 - 248 Sep 01 01:53:12 spla-repro volumio[28431]: Mono: 112 [45%] Sep 01 01:53:12 spla-repro volumio[28431]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreStateMachine::pushState Sep 01 01:53:12 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:12 spla-repro volumio[28431]: info: Asound.conf file unchanged, so no further update is needed Sep 01 01:53:12 spla-repro volumio[28431]: info: Output device has changed, restarting MPD Sep 01 01:53:12 spla-repro volumio[28431]: info: Output device has changed, restarting Shairport Sync Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:12 spla-repro sudo[28572]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:12 spla-repro sudo[28574]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:12 spla-repro volumio[28431]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:12 spla-repro volumio[28431]: info: ___________ START PLUGINS ___________ Sep 01 01:53:12 spla-repro sudo[28574]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:53:12 spla-repro sudo[28572]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:53:12 spla-repro sudo[28572]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:12 spla-repro sudo[28574]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:12 spla-repro sudo[28572]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:12 spla-repro volumio[28431]: info: ControllerMpd::onStart: Initializing MPD Sep 01 01:53:12 spla-repro volumio[28431]: info: Creating MPD Configuration file Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:12 spla-repro volumio[28431]: info: [1788220392810] CoreMusicLibrary::Adding element Mediálne servery Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:12 spla-repro sudo[28582]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:12 spla-repro volumio[28431]: info: UPNP Browser: Client initialized successfully Sep 01 01:53:12 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Sep 01 01:53:12 spla-repro sudo[28586]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:12 spla-repro sudo[28582]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Sep 01 01:53:12 spla-repro sudo[28582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:12 spla-repro sudo[28584]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:12 spla-repro sudo[28586]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:53:12 spla-repro sudo[28586]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:12 spla-repro sudo[28584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:53:12 spla-repro sudo[28584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:12 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:53:12 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:53:12 spla-repro sudo[28584]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:12 spla-repro systemd[1]: mpd.service: Consumed 4.049s CPU time. Sep 01 01:53:12 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:53:12 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:53:12 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:53:12 spla-repro volumio[28431]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:12 spla-repro volumio[28431]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:12 spla-repro volumio[28431]: info: [1788220392993] CoreMusicLibrary::Adding element Last_100 Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:12 spla-repro volumio[28431]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:13 spla-repro volumio[28431]: info: [1788220393000] CoreMusicLibrary::Adding element Webradio Sep 01 01:53:13 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:13 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:53:13 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:53:13 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:13 spla-repro volumio[28431]: info: Initializing BBC Radios Sep 01 01:53:13 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:53:13 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:53:13 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:53:13 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:53:13 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:53:13 spla-repro sudo[28582]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:13 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:53:13 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:53:13 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:13 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:13 spla-repro volumio[28431]: info: Creating Spotify config file Sep 01 01:53:13 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:13 spla-repro sudo[28614]: root : unable to resolve host spla-repro: System error Sep 01 01:53:13 spla-repro sudo[28614]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:13 spla-repro sudo[28614]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 01:53:13 spla-repro sudo[28614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 01 01:53:13 spla-repro sudo[28614]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:13 spla-repro volumio[28431]: info: Volumio Calling Home Sep 01 01:53:13 spla-repro volumio[28533]: Starting albumart workers Sep 01 01:53:14 spla-repro volumio[28532]: Starting albumart workers Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: Found device Spálňa-repro Sep 01 01:53:14 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:14 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:14 spla-repro volumio[28534]: Starting albumart workers Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: Connected to remote: 192.168.200.201 Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: Connected to remote: 192.168.200.202 Sep 01 01:53:14 spla-repro volumio[28431]: info: MPD Permissions set Sep 01 01:53:14 spla-repro volumio[28431]: info: MPD Permissions set Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:53:14 spla-repro volumio[28431]: info: Discovery: Found device Spálňa-repro Sep 01 01:53:14 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:14 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:14 spla-repro volumio[28431]: info: Volumio called home Sep 01 01:53:14 spla-repro volumio[28431]: info: Spotify config file written Sep 01 01:53:14 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:53:14 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:14 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:14 spla-repro sudo[28622]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:14 spla-repro sudo[28622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 01 01:53:14 spla-repro sudo[28622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:14 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Sep 01 01:53:14 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:15 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:15 spla-repro go-librespot[28624]: go-librespot daemon starting... Sep 01 01:53:15 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 01 01:53:15 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 01 01:53:15 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:15 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:15 spla-repro go-librespot[28631]: go-librespot daemon starting... Sep 01 01:53:15 spla-repro sudo[28622]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:15 spla-repro volumio[28431]: 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 Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="app state loaded" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:15 spla-repro volumio[28431]: info: No need to fix Spotify hosts Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+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]" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+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]" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=info msg="zeroconf server listening on port 34279" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:15 spla-repro volumio[28431]: info: An error occurred while refreshing Spotify Token Error: Bad Request Sep 01 01:53:15 spla-repro volumio[28431]: info: Starting Shairport Sync Sep 01 01:53:15 spla-repro volumio[28431]: info: Starting Shairport Sync Sep 01 01:53:15 spla-repro volumio[28431]: info: Starting Shairport Sync Sep 01 01:53:15 spla-repro sudo[28671]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:15 spla-repro sudo[28671]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:15 spla-repro sudo[28673]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:15 spla-repro sudo[28671]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="obtained new client token: AAG4kglCfQkH53NJ4rySGy4+sZxcZtkutNjjFBGWhEDx3e256zcilkgU1IK8R+sOhasQdGnzCGv38cEm9haOsd7IbwCLrj9JJ19/DhiNFG3rmkriCMoLJB2ejb79B2w0MPtaLl0VR08Iv/E2zYMxBTRjnfDY71Gg8Wn+6pQq+y8P845z576DrCTmYlKc13B1ejZF2ia92GL3YY+2P/WXKS1zqQw5/zC8UZrfjyW/A7dlWmMMWOhVTiCz8Q==" Sep 01 01:53:15 spla-repro sudo[28673]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:15 spla-repro sudo[28673]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:15 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:15 spla-repro sudo[28675]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:15 spla-repro sudo[28675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:15 spla-repro sudo[28675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+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" Sep 01 01:53:15 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:15 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Sep 01 01:53:15 spla-repro volumio[28431]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="connected to ap-gew1.spotify.com:80" Sep 01 01:53:15 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 01 01:53:15 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Sep 01 01:53:15 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:15 spla-repro systemd[1]: shairport-sync.service: Consumed 1.856s CPU time. Sep 01 01:53:15 spla-repro volumio[28431]: 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 Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:15 spla-repro go-librespot[28632]: time="2026-09-01T01:53:15+02:00" level=debug msg="completed challenge" Sep 01 01:53:15 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:15 spla-repro sudo[28673]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:15 spla-repro volumio[28431]: info: Listing playlists Sep 01 01:53:15 spla-repro volumio[28431]: info: Listing playlists Sep 01 01:53:15 spla-repro sudo[28671]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:16 spla-repro sudo[28675]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:16 spla-repro go-librespot[28632]: time="2026-09-01T01:53:16+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:16 spla-repro volumio[28431]: info: Shairport-Sync Started Sep 01 01:53:16 spla-repro volumio[28431]: Error adding Membership: Error: addMembership EINVAL Sep 01 01:53:16 spla-repro volumio[28431]: info: Shairport-Sync Started Sep 01 01:53:16 spla-repro volumio[28431]: info: Shairport-Sync Started Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:16 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:16 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:16 spla-repro go-librespot[28632]: time="2026-09-01T01:53:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:16 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:16 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:16 spla-repro volumio[28431]: 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 Sep 01 01:53:17 spla-repro mpd[28616]: 2026-09-01T01:53:17 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 01:53:17 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Sep 01 01:53:17 spla-repro sudo[28586]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:17 spla-repro sudo[28574]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:17 spla-repro volumio[28431]: info: Completed starting Core Plugins Sep 01 01:53:17 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:17 spla-repro volumio[28431]: info: ----- MyVolumio plugins startup ---- Sep 01 01:53:17 spla-repro volumio[28431]: info: ------------------------------------------- Sep 01 01:53:17 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 01 01:53:17 spla-repro volumio[28431]: error: MPD error: The expression evaluated to a falsy value: Sep 01 01:53:17 spla-repro volumio[28431]: assert.ok(self.idling) Sep 01 01:53:17 spla-repro volumio[28431]: error: The expression evaluated to a falsy value: Sep 01 01:53:17 spla-repro volumio[28431]: assert.ok(self.idling) Sep 01 01:53:17 spla-repro volumio[28431]: error: updateQueue error: null Sep 01 01:53:17 spla-repro volumio[28431]: info: MPD running with PID28616 Sep 01 01:53:17 spla-repro volumio[28431]: ,establishing connection Sep 01 01:53:17 spla-repro volumio[28431]: error: updateQueue error: null Sep 01 01:53:18 spla-repro sudo[28713]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:18 spla-repro sudo[28715]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:18 spla-repro sudo[28713]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:53:18 spla-repro sudo[28713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:18 spla-repro sudo[28715]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:53:18 spla-repro sudo[28713]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:18 spla-repro sudo[28715]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:18 spla-repro sudo[28717]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:18 spla-repro sudo[28715]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:18 spla-repro sudo[28717]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 01 01:53:18 spla-repro sudo[28717]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:18 spla-repro sudo[28717]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:18 spla-repro volumio[28431]: info: Upmpdcli Daemon Started Sep 01 01:53:18 spla-repro volumio[28431]: info: go-librespot daemon successfully initialized Sep 01 01:53:19 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:19.005+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" Sep 01 01:53:19 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Sep 01 01:53:19 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:19 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:19 spla-repro go-librespot[28721]: go-librespot daemon starting... Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="app state loaded" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=info msg="zeroconf server listening on port 43293" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="obtained new client token: AAGKV1KoR5VYm/myd+8/OMKnnI0/1x5koMmC7MScRS4LjbsxjttIZYrZ58/PAkdNw+IIl2SIk6x/8tdo6Wf6wkejsUJgfLG/Y/V7gwfwVQaBJ+ZNi3Kd+UJcE8oBZ3B0WJ2P8t6hoSVZiHUQR0w3MMPivNw64vCgpWwz5JQwz3ivey7CCxUthvso/Ze1RZ+AOZQPlvTkW7THiagswTmsarYBhXeExQlmKqFn4q7Df+SR05K8PitHx88hKw==" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=debug msg="completed challenge" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:19 spla-repro go-librespot[28722]: time="2026-09-01T01:53:19+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:19 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:19 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:21 spla-repro volumio[28431]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:21 spla-repro volumio[28431]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:22 spla-repro volumio[28431]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Sep 01 01:53:22 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:22 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:22 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Sep 01 01:53:22 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:23 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:23 spla-repro go-librespot[28731]: go-librespot daemon starting... Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=debug msg="app state loaded" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+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]" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+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]" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+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]" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=info msg="zeroconf server listening on port 39523" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=debug msg="obtained new client token: AAEzVbxUUjNpzPOBjGxu1h3Qq3bvwsHa4lIEHopvS51e2nBK1fDuMx9c0UfEoxgNKhcJUjoLEqTppnkVz8y7ANZ3vKObK1aCCASJyNiMgpYykFNM64MhODJyXcetSXA7lV5NnGlxIx2MXHA5amM4E5ajA6E+GX/gb8IEKUGyY7gnHXWJda5IQHZGNdXl+jJskYQMq/asXSOClUtx/Kw5e/sruXKamahxal9fzFRfQ0GHyEckaXzjpRaYQQ==" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=debug msg="completed challenge" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:23 spla-repro go-librespot[28732]: time="2026-09-01T01:53:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:23 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:23 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:24 spla-repro volumio[28431]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:24 spla-repro volumio[28431]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin bluetooth to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin multiroom to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin metavolumio to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin cd_controller to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 01 01:53:25 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 01 01:53:26 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Sep 01 01:53:26 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:26 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:26 spla-repro go-librespot[28741]: go-librespot daemon starting... Sep 01 01:53:26 spla-repro go-librespot[28742]: time="2026-09-01T01:53:26+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:26 spla-repro go-librespot[28742]: time="2026-09-01T01:53:26+02:00" level=debug msg="app state loaded" Sep 01 01:53:26 spla-repro go-librespot[28742]: time="2026-09-01T01:53:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:27 spla-repro volumio[28431]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 01 01:53:27 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 01 01:53:27 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:27 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:27 spla-repro volumio[28431]: info: Starting MyVolumio Remote Streaming Endpoints Sep 01 01:53:27 spla-repro volumio[28431]: info: MyVolumio login type: Token Sep 01 01:53:27 spla-repro volumio[28431]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 01 01:53:27 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+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]" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+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]" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+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]" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=info msg="zeroconf server listening on port 41781" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=debug msg="obtained new client token: AAFy54yIFgtMqX/0QJQzA7zCiby6ehfIm4HP/SmcsvpVh+csSzBD47aeCIvN51vEx4j13QkGANpZkR3dqQkIhMSq2rKa4IQL4iWuB1DxawV3DFudEhzF03BDlebauwrVL+6GHEUrZx427uyvkTjvzMcZh1uCIlhQsDZmAyLWlq7rW0p6LTvYQsUIEdBrYZ+nnbrETcFgGmLjvKoi598GB2A4ju7SWeKcE3B7vINfhSypgOy/DimhNmhJdA==" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=debug msg="completed challenge" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:27 spla-repro go-librespot[28742]: time="2026-09-01T01:53:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:27 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:27 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:28 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 01 01:53:28 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 01 01:53:28 spla-repro volumio[28431]: info: Streaming services startup Sep 01 01:53:28 spla-repro volumio[28431]: info: Starting Streaming Daemon Sep 01 01:53:28 spla-repro sudo[28767]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:28 spla-repro volumio[28431]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 01 01:53:28 spla-repro sudo[28767]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 01 01:53:28 spla-repro sudo[28767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:28 spla-repro sudo[28767]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:28 spla-repro volumio[28431]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:28 spla-repro volumio[28431]: error: Cannot start Volumio Streaming Daemon Sep 01 01:53:28 spla-repro volumio[28431]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 01 01:53:28 spla-repro volumio[28431]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:28 spla-repro volumio[28431]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 01 01:53:28 spla-repro volumio[28431]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:28 spla-repro volumio[28431]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Sep 01 01:53:29 spla-repro volumio[28431]: info: MyVolumio token set successfully Sep 01 01:53:29 spla-repro volumio[28431]: info: MYVOLUMIO: Adding device Sep 01 01:53:29 spla-repro volumio[28431]: info: MYVOLUMIO: Evaluating Server Sep 01 01:53:29 spla-repro volumio[28431]: info: MyVolumio status changed Sep 01 01:53:29 spla-repro volumio[28431]: info: Streaming services startup Sep 01 01:53:29 spla-repro volumio[28431]: info: Starting Streaming Daemon Sep 01 01:53:29 spla-repro volumio[28431]: info: Removing browser output: myVolumio user plan is not superstar Sep 01 01:53:29 spla-repro volumio[28431]: info: Removing audio output: Sep 01 01:53:29 spla-repro volumio[28431]: info: Stoppping Tunnel 1 Sep 01 01:53:29 spla-repro sudo[28794]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:29 spla-repro sudo[28794]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 01 01:53:29 spla-repro sudo[28794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:29 spla-repro sudo[28794]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:30 spla-repro sudo[28797]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:30 spla-repro sudo[28797]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Sep 01 01:53:30 spla-repro sudo[28797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:30 spla-repro volumio[28431]: error: Cannot start Volumio Streaming Daemon Sep 01 01:53:30 spla-repro volumio[28431]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 01 01:53:30 spla-repro volumio[28431]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:30 spla-repro volumio[28431]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 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. Sep 01 01:53:30 spla-repro sudo[28797]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:30 spla-repro volumio[28431]: info: Remote SSH Stopped Sep 01 01:53:30 spla-repro volumio[28431]: info: Setting Geolocation for MyVolumio to eu6 Sep 01 01:53:30 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:30 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:30 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:30 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Sep 01 01:53:30 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:30 spla-repro volumio[28431]: info: Successfully Added MyVolumio device Sep 01 01:53:30 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:30 spla-repro go-librespot[28799]: go-librespot daemon starting... Sep 01 01:53:30 spla-repro go-librespot[28800]: time="2026-09-01T01:53:30+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:30 spla-repro go-librespot[28800]: time="2026-09-01T01:53:30+02:00" level=debug msg="app state loaded" Sep 01 01:53:30 spla-repro go-librespot[28800]: time="2026-09-01T01:53:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+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]" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+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]" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+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]" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=info msg="zeroconf server listening on port 41231" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:31 spla-repro volumio[28431]: info: Updating MyVolumio device info Sep 01 01:53:31 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:31 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:31 spla-repro volumio[28431]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=debug msg="obtained new client token: AAGNSRr7ZygwDR2vas+6wmt8PiVIZPOR7NfuXHtuucbqU0MOJvg/jGRbeELmjkt8YfLvajO0F9PoqwwWKEDB0TG6JYHaCgV5IJF3FJRJ8V4mjx8/1KPy8hOfa8ZEtQPlISE8f4tYkq6BwZtyWsngvzVpzJlmtIVED3Y6EkOAE6NkwkraMtxsJqMTF7ZXzJK8h9iYKVQHYcmcjwjT4vmDXnUy1lrxtYWwcvUu4iL1gcS1ZJL2be+rusc=" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:31 spla-repro volumio[28431]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=debug msg="new websocket client" Sep 01 01:53:31 spla-repro volumio[28431]: info: Connection to go-librespot Websocket established Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=debug msg="completed challenge" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:31 spla-repro go-librespot[28800]: time="2026-09-01T01:53:31+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:31 spla-repro volumio[28431]: info: Connection to go-librespot Websocket closed Sep 01 01:53:31 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:31 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:31 spla-repro volumio[28431]: info: Successfully Updated MyVolumio device Sep 01 01:53:32 spla-repro volumio[28431]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:32 spla-repro volumio[28431]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:32 spla-repro volumio[28431]: info: Listing playlists Sep 01 01:53:32 spla-repro volumio[28431]: info: Listing playlists Sep 01 01:53:34 spla-repro volumio[28431]: info: Getting Spotify volume Sep 01 01:53:34 spla-repro volumio[28431]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:53:34 spla-repro volumio[28431]: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:34 spla-repro volumio[28431]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Sep 01 01:53:34 spla-repro volumio[28431]: errno: -111, Sep 01 01:53:34 spla-repro volumio[28431]: code: 'ECONNREFUSED', Sep 01 01:53:34 spla-repro volumio[28431]: syscall: 'connect', Sep 01 01:53:34 spla-repro volumio[28431]: address: '127.0.0.1', Sep 01 01:53:34 spla-repro volumio[28431]: port: 9879, Sep 01 01:53:34 spla-repro volumio[28431]: response: undefined Sep 01 01:53:34 spla-repro volumio[28431]: } Sep 01 01:53:34 spla-repro volumio[28431]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:53:34 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Sep 01 01:53:34 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:34 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:34 spla-repro go-librespot[28821]: go-librespot daemon starting... Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=debug msg="app state loaded" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+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]" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+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]" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+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]" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=info msg="zeroconf server listening on port 44745" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:34 spla-repro go-librespot[28823]: time="2026-09-01T01:53:34+02:00" level=debug msg="obtained new client token: AAGZKLFYqkuQMQKSG5b/sFa0Quyg9vLBz8MRx0dlj5VA5jfW5kD21lqxH/SVnH/YQM9Pl2/lpEECHQlJhXbGpHaF/+MooSDfRjmXO2uWQzIJQ3B4HTQCjUrlvgDufaylEAhGxJFKqrVPVNC877iQ8asAhV+ZNSGmrqLHODBSBsXw5mEOmQJxl5IL7G2grW5hwJz4m72sdF4chKvN0hGOm+GFhwxyciZanH8ywJ8QAqg5u6trulfHafQzLA==" Sep 01 01:53:35 spla-repro go-librespot[28823]: time="2026-09-01T01:53:35+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:35 spla-repro sudo[28834]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:35 spla-repro sudo[28834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-01 01:52' Sep 01 01:53:35 spla-repro sudo[28834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:35 spla-repro go-librespot[28823]: time="2026-09-01T01:53:35+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:35 spla-repro go-librespot[28823]: time="2026-09-01T01:53:35+02:00" level=debug msg="completed challenge" Sep 01 01:53:35 spla-repro go-librespot[28823]: time="2026-09-01T01:53:35+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:35 spla-repro go-librespot[28823]: time="2026-09-01T01:53:35+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:35 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:35 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:35 spla-repro sudo[28834]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:35 spla-repro volumio[28431]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:35 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:35] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Sep 01 01:53:35 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:35] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Sep 01 01:53:35 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:35.358+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Sep 01 01:53:35 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:35 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:35.361+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:53:35 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Sep 01 01:53:35 spla-repro systemd[1]: volumio.service: Consumed 28.115s CPU time. Sep 01 01:53:35 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:53:35 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:53:35 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 15809. Sep 01 01:53:35 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:53:35 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Sep 01 01:53:35 spla-repro systemd[1]: volumio.service: Consumed 28.115s CPU time. Sep 01 01:53:35 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Sep 01 01:53:35 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:53:36 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:36.365+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:53:37 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:37 spla-repro volumio[28851]: info: ----- Volumio3 ---- Sep 01 01:53:37 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:37 spla-repro volumio[28851]: info: ----- System startup ---- Sep 01 01:53:37 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:38 spla-repro volumio[28851]: info: MYVOLUMIO Environment detected Sep 01 01:53:38 spla-repro volumio[28851]: info: Plugin folders cleanup Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning into folder /volumio/app/plugins/ Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category audio_interface Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category miscellanea Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category music_service Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category plugins.json Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category system_controller Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category user_interface Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning into folder /data/plugins/ Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category audio_interface Sep 01 01:53:38 spla-repro volumio[28851]: info: Scanning category music_service Sep 01 01:53:38 spla-repro volumio[28851]: info: Plugin folders cleanup completed Sep 01 01:53:38 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:38 spla-repro volumio[28851]: info: ----- Core plugins startup ---- Sep 01 01:53:38 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:38 spla-repro volumio[28851]: info: Loading plugins from folder /volumio/app/plugins/ Sep 01 01:53:38 spla-repro volumio[28851]: info: Adding plugin upnp to MyMusic Plugins Sep 01 01:53:38 spla-repro volumio[28851]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 01 01:53:38 spla-repro volumio[28851]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 01 01:53:38 spla-repro volumio[28851]: info: Loading plugins from folder /data/plugins/ Sep 01 01:53:38 spla-repro volumio[28851]: info: Loading plugin "system"... Sep 01 01:53:38 spla-repro volumio[28851]: info: Loading plugin "appearance"... Sep 01 01:53:38 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Sep 01 01:53:38 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:38 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:38 spla-repro go-librespot[28878]: go-librespot daemon starting... Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+02:00" level=debug msg="app state loaded" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+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]" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+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]" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+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]" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+02:00" level=info msg="zeroconf server listening on port 43409" Sep 01 01:53:38 spla-repro go-librespot[28879]: time="2026-09-01T01:53:38+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=debug msg="obtained new client token: AAHoIuc61kkv52h//ZZfaylVUcU8KW4VBFRHlzTg7CZUn677ZsXFeBr5kb+n5Xgukommgn7j3PuhqP10yTvOA3h4J5RF31zhpPHp6Zniq/pPJNBAgBuLaxZwGFCuJMgNJMhupfZuDONd1vtx7s72O6U8LF6Px607/rGyA1e8a15J0gMXDAXAcRUFztiU3hyQgOeu/w366MH4dcZOLbZvZbTAj7c7SUNM/Lk+r6HuFvgWZDQaAJMfP+k=" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=debug msg="completed challenge" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:39 spla-repro go-librespot[28879]: time="2026-09-01T01:53:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:39 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:39 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "network"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Refreshing Cached IP Addresses Sep 01 01:53:39 spla-repro sudo[28889]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:39 spla-repro sudo[28891]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:39 spla-repro sudo[28889]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:53:39 spla-repro sudo[28889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:39 spla-repro sudo[28891]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:53:39 spla-repro sudo[28891]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:39 spla-repro sudo[28889]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "services"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "volumio5onboarding"... Sep 01 01:53:39 spla-repro sudo[28891]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:39 spla-repro sudo[28898]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "alsa_controller"... Sep 01 01:53:39 spla-repro sudo[28898]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 01 01:53:39 spla-repro sudo[28898]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:39 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "wizard"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "networkfs"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Starting Udev Watcher for removable devices Sep 01 01:53:39 spla-repro volumio[28851]: info: Ignoring mount for partition: boot Sep 01 01:53:39 spla-repro volumio[28851]: info: Ignoring mount for partition: volumio Sep 01 01:53:39 spla-repro volumio[28851]: info: Ignoring mount for partition: volumio_data Sep 01 01:53:39 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "volumio_command_line_client"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "upnp"... Sep 01 01:53:39 spla-repro volumio[28851]: info: [1788220419716] Starting Upmpd Daemon Sep 01 01:53:39 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "my_music"... Sep 01 01:53:39 spla-repro volumio[28851]: info: Loading plugin "mpd"... Sep 01 01:53:40 spla-repro volumio[28851]: info: Loading plugin "upnp_browser"... Sep 01 01:53:40 spla-repro sudo[28898]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:40 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:40] [connect] Successful connection Sep 01 01:53:41 spla-repro volumio[28851]: info: Starting UPNP Browser Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "alarm-clock"... Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "airplay_emulation"... Sep 01 01:53:41 spla-repro volumio[28851]: info: Starting Shairport Sync Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "last_100"... Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "webradio"... Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "i2s_dacs"... Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "volumiodiscovery"... Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** For more information see Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:41 spla-repro volumio[28851]: *** WARNING *** For more information see Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** For more information see Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:53:41 spla-repro node[28851]: *** WARNING *** For more information see Sep 01 01:53:41 spla-repro volumio[28851]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 01 01:53:41 spla-repro volumio[28851]: info: Discovery: Started advertising with name: Spálňa-repro Sep 01 01:53:41 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:53:41 spla-repro volumio[28851]: info: Loading plugin "spop"... Sep 01 01:53:42 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Sep 01 01:53:42 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:42 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:42 spla-repro go-librespot[28924]: go-librespot daemon starting... Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=debug msg="app state loaded" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+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]" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+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]" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+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]" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=info msg="zeroconf server listening on port 45833" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:42 spla-repro go-librespot[28925]: time="2026-09-01T01:53:42+02:00" level=debug msg="obtained new client token: AAFUBqtTKAROBkXmi2QdSf+hDJvA1OoNzDCnoWbb6lGzBp5qUHtYriEHwm3tYcHzTgLlkH4T2gyyl50/Y7up3SZLDNIkkj6YMDCb1d/N9shA2JFxiO33tlRizgZxSybGaGfnEGmi8htJAYgOJiuU9Bep/yMTYlacG8Gkd0fwIHi5GEsQtMh8hLMGNuq+7e2dKpFz76rpJoj0QGMQWr60x8OkDbtV77CF3i61hYriks+JcpQA+faf+ZBONQ==" Sep 01 01:53:43 spla-repro go-librespot[28925]: time="2026-09-01T01:53:43+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:43 spla-repro go-librespot[28925]: time="2026-09-01T01:53:43+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:43 spla-repro go-librespot[28925]: time="2026-09-01T01:53:43+02:00" level=debug msg="completed challenge" Sep 01 01:53:43 spla-repro go-librespot[28925]: time="2026-09-01T01:53:43+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "outputs"... Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "albumart"... Sep 01 01:53:43 spla-repro volumio[28851]: info: Plugin example_plugin is not enabled Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "inputs"... Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "updater_comm"... Sep 01 01:53:43 spla-repro go-librespot[28925]: time="2026-09-01T01:53:43+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:43 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:43 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:43 spla-repro volumio[28851]: info: Plugin mpdemulation is not enabled Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "rest_api"... Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading plugin "websocket"... Sep 01 01:53:43 spla-repro volumio[28851]: info: Starting Socket.io Server version 1.7.4 Sep 01 01:53:43 spla-repro volumio[28851]: info: Plugin fusiondsp is not enabled Sep 01 01:53:43 spla-repro volumio[28851]: info: Loading i18n strings for locale sk Sep 01 01:53:43 spla-repro volumio[28851]: Updating browse sources language Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::initPlayerControls Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: Express server listening on port 3000 Sep 01 01:53:43 spla-repro volumio[28851]: [Metrics] WebUI: 6s 559.60ms Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::resetVolumioState Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::getcurrentVolume Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:53:43 spla-repro volumio[28851]: info: Cannot read play queue from file Sep 01 01:53:43 spla-repro volumio[28851]: info: Volumio Network Manager: Network status updated: 1 Sep 01 01:53:43 spla-repro volumio[28851]: 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 Sep 01 01:53:43 spla-repro volumio[28851]: Unable to parse: Sep 01 01:53:43 spla-repro volumio[28851]: Simple mixer control 'Master',0 Sep 01 01:53:43 spla-repro volumio[28851]: Capabilities: volume volume-joined Sep 01 01:53:43 spla-repro volumio[28851]: Playback channels: Mono Sep 01 01:53:43 spla-repro volumio[28851]: Capture channels: Mono Sep 01 01:53:43 spla-repro volumio[28851]: Limits: 0 - 248 Sep 01 01:53:43 spla-repro volumio[28851]: Mono: 112 [45%] Sep 01 01:53:43 spla-repro volumio[28851]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:53:43 spla-repro volumio[28934]: Forking 3 albumart workers Sep 01 01:53:43 spla-repro volumio[28851]: 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 Sep 01 01:53:43 spla-repro volumio[28851]: info: Received Get System Info Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 01:53:43 spla-repro volumio[28851]: info: Discovery: Getting this device information Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:43 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 01:53:43 spla-repro volumio[28851]: 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 Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 01 01:53:43 spla-repro volumio[28851]: 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 Sep 01 01:53:43 spla-repro volumio[28851]: Unable to parse: Sep 01 01:53:43 spla-repro volumio[28851]: Simple mixer control 'Master',0 Sep 01 01:53:43 spla-repro volumio[28851]: Capabilities: volume volume-joined Sep 01 01:53:43 spla-repro volumio[28851]: Playback channels: Mono Sep 01 01:53:43 spla-repro volumio[28851]: Capture channels: Mono Sep 01 01:53:43 spla-repro volumio[28851]: Limits: 0 - 248 Sep 01 01:53:43 spla-repro volumio[28851]: Mono: 112 [45%] Sep 01 01:53:43 spla-repro volumio[28851]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::pushState Sep 01 01:53:43 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::updateTrackBlock Sep 01 01:53:43 spla-repro volumio[28851]: info: CorePlayQueue::getTrackBlock Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::setRepeat null single undefined Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::pushState Sep 01 01:53:43 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::setRandom null Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreStateMachine::pushState Sep 01 01:53:43 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:43 spla-repro volumio[28851]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:43 spla-repro volumio[28851]: info: Setting Device type: Raspberry PI Sep 01 01:53:43 spla-repro volumio-remote-updater[725]: [2026-09-01 01:53:43] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788220420 101 Sep 01 01:53:43 spla-repro volumio[28851]: 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 Sep 01 01:53:43 spla-repro volumio[28851]: info: Completed loading Core Plugins Sep 01 01:53:43 spla-repro volumio[28851]: info: Preparing to generate the ALSA configuration file Sep 01 01:53:44 spla-repro volumio[28851]: Unable to parse: Sep 01 01:53:44 spla-repro volumio[28851]: Simple mixer control 'Master',0 Sep 01 01:53:44 spla-repro volumio[28851]: Capabilities: volume volume-joined Sep 01 01:53:44 spla-repro volumio[28851]: Playback channels: Mono Sep 01 01:53:44 spla-repro volumio[28851]: Capture channels: Mono Sep 01 01:53:44 spla-repro volumio[28851]: Limits: 0 - 248 Sep 01 01:53:44 spla-repro volumio[28851]: Mono: 112 [45%] Sep 01 01:53:44 spla-repro volumio[28851]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:44 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: Found device kuchyna-repro Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: Connecting to remote: 192.168.200.201 Sep 01 01:53:44 spla-repro volumio[28851]: 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 Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: Found device kupelna-repro Sep 01 01:53:44 spla-repro volumio[28851]: info: Discovery: Connecting to remote: 192.168.200.202 Sep 01 01:53:44 spla-repro volumio[28851]: 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 Sep 01 01:53:44 spla-repro volumio[28851]: Unable to parse: Sep 01 01:53:44 spla-repro volumio[28851]: Simple mixer control 'Master',0 Sep 01 01:53:44 spla-repro volumio[28851]: Capabilities: volume volume-joined Sep 01 01:53:44 spla-repro volumio[28851]: Playback channels: Mono Sep 01 01:53:44 spla-repro volumio[28851]: Capture channels: Mono Sep 01 01:53:44 spla-repro volumio[28851]: Limits: 0 - 248 Sep 01 01:53:44 spla-repro volumio[28851]: Mono: 112 [45%] Sep 01 01:53:44 spla-repro volumio[28851]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreStateMachine::pushState Sep 01 01:53:44 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::volumioPushState Sep 01 01:53:44 spla-repro volumio[28851]: info: Asound.conf file unchanged, so no further update is needed Sep 01 01:53:44 spla-repro volumio[28851]: info: Output device has changed, restarting MPD Sep 01 01:53:44 spla-repro volumio[28851]: info: Output device has changed, restarting Shairport Sync Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:44 spla-repro sudo[28991]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:44 spla-repro sudo[28991]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:53:44 spla-repro sudo[28991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:44 spla-repro volumio[28851]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:44 spla-repro sudo[28994]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:44 spla-repro sudo[28991]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:44 spla-repro volumio[28851]: info: ___________ START PLUGINS ___________ Sep 01 01:53:44 spla-repro sudo[28994]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:53:44 spla-repro sudo[28994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:44 spla-repro volumio[28851]: info: ControllerMpd::onStart: Initializing MPD Sep 01 01:53:44 spla-repro volumio[28851]: info: Creating MPD Configuration file Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:44 spla-repro volumio[28851]: info: [1788220424639] CoreMusicLibrary::Adding element Mediálne servery Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:44 spla-repro sudo[29003]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:44 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Sep 01 01:53:44 spla-repro sudo[29001]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:44 spla-repro volumio[28851]: info: UPNP Browser: Client initialized successfully Sep 01 01:53:44 spla-repro sudo[29003]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:53:44 spla-repro sudo[29003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:44 spla-repro sudo[29001]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Sep 01 01:53:44 spla-repro sudo[29001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:44 spla-repro sudo[29005]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:44 spla-repro sudo[29003]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:44 spla-repro sudo[29005]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:53:44 spla-repro sudo[29005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:44 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:53:44 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:53:44 spla-repro systemd[1]: mpd.service: Consumed 4.289s CPU time. Sep 01 01:53:44 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:53:44 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:53:44 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:53:44 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:53:44.817+02:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 01 01:53:44 spla-repro volumio[28851]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:44 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:53:44 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:53:44 spla-repro sudo[29001]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:44 spla-repro volumio[28851]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:53:44 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:44 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:53:44 spla-repro volumio[28851]: info: [1788220424915] CoreMusicLibrary::Adding element Last_100 Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:44 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:53:44 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:53:44 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:53:44 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:53:44 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:53:44 spla-repro volumio[28851]: info: [1788220424933] CoreMusicLibrary::Adding element Webradio Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:53:44 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:44 spla-repro volumio[28851]: info: Initializing BBC Radios Sep 01 01:53:45 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:53:45 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:45 spla-repro volumio[28851]: info: Creating Spotify config file Sep 01 01:53:45 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:45 spla-repro sudo[29020]: root : unable to resolve host spla-repro: System error Sep 01 01:53:45 spla-repro sudo[29020]: sudo: unable to resolve host spla-repro: System error Sep 01 01:53:45 spla-repro sudo[29020]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 01:53:45 spla-repro sudo[29020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 01 01:53:45 spla-repro sudo[29020]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:45 spla-repro volumio[28953]: Starting albumart workers Sep 01 01:53:45 spla-repro volumio[28951]: Starting albumart workers Sep 01 01:53:45 spla-repro volumio[28952]: Starting albumart workers Sep 01 01:53:45 spla-repro volumio[28851]: info: Volumio Calling Home Sep 01 01:53:46 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:53:46 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Sep 01 01:53:46 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:46 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:46 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:46 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:46 spla-repro go-librespot[29039]: go-librespot daemon starting... Sep 01 01:53:46 spla-repro go-librespot[29041]: time="2026-09-01T01:53:46+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: Connected to remote: 192.168.200.201 Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: Found device Spálňa-repro Sep 01 01:53:46 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:46 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: Found device Spálňa-repro Sep 01 01:53:46 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:46 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:46 spla-repro volumio[28851]: info: Discovery: Connected to remote: 192.168.200.202 Sep 01 01:53:47 spla-repro volumio[28851]: info: MPD Permissions set Sep 01 01:53:47 spla-repro volumio[28851]: info: MPD Permissions set Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:53:47 spla-repro volumio[28851]: info: Volumio called home Sep 01 01:53:47 spla-repro go-librespot[29041]: time="2026-09-01T01:53:47+02:00" level=info msg="zeroconf server listening on port 45185" Sep 01 01:53:47 spla-repro go-librespot[29041]: time="2026-09-01T01:53:47+02:00" level=info msg="using built-in mDNS responder" Sep 01 01:53:47 spla-repro volumio[28851]: info: Spotify config file written Sep 01 01:53:47 spla-repro sudo[29062]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:47 spla-repro sudo[29062]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 01 01:53:47 spla-repro sudo[29062]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:47 spla-repro systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Sep 01 01:53:47 spla-repro systemd[1]: go-librespot-daemon.service: Deactivated successfully. Sep 01 01:53:47 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:47 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:47 spla-repro go-librespot[29070]: go-librespot daemon starting... Sep 01 01:53:47 spla-repro sudo[29062]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=debug msg="app state loaded" Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:53:47 spla-repro volumio[28851]: info: No need to fix Spotify hosts Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:47 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:47 spla-repro volumio[28851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Sep 01 01:53:47 spla-repro volumio[28851]: info: An error occurred while refreshing Spotify Token Error: Bad Request Sep 01 01:53:47 spla-repro volumio[28851]: info: Starting Shairport Sync Sep 01 01:53:47 spla-repro volumio[28851]: info: Starting Shairport Sync Sep 01 01:53:47 spla-repro volumio[28851]: info: Starting Shairport Sync Sep 01 01:53:47 spla-repro sudo[29091]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:47 spla-repro sudo[29091]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:47 spla-repro sudo[29091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:47 spla-repro sudo[29093]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:47 spla-repro sudo[29093]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:47 spla-repro sudo[29093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:47 spla-repro sudo[29095]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:47 spla-repro sudo[29095]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:53:47 spla-repro sudo[29095]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 01 01:53:47 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 01 01:53:47 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Sep 01 01:53:47 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:47 spla-repro systemd[1]: shairport-sync.service: Consumed 1.866s CPU time. Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=info msg="zeroconf server listening on port 35551" Sep 01 01:53:47 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:47 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:47 spla-repro go-librespot[29071]: time="2026-09-01T01:53:47+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:47 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:47 spla-repro sudo[29093]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:47 spla-repro volumio[28851]: info: Shairport-Sync Started Sep 01 01:53:47 spla-repro volumio[28851]: Error adding Membership: Error: addMembership EINVAL Sep 01 01:53:48 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 01 01:53:48 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Sep 01 01:53:48 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:48 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:53:48 spla-repro sudo[29091]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:48 spla-repro sudo[29095]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:48 spla-repro volumio[28851]: info: Shairport-Sync Started Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=debug msg="obtained new client token: AAH3TJIm2EvE9En7JzbsEGrFzhqezuV1WNlqQNw1xzEJmNaBezthnI+Q6nFUsOLLE3zjoezJ7A1LlxJRwlLdVjcrId9Pu2SQ8o2Do19a9Bgi70FdsO8p5prH9rG6GHcm+NzmAvKkgAxXyHnbw7dVr3Qsdqixz/MVF6Zv6zVprpa3sbzziQeWfHLR8Meqlt2gDTORX2ZWKfjvm9qU1iKAGYI+4RBx3008Ibx1x06tPyk7DhdOnQdXqWU=" Sep 01 01:53:48 spla-repro volumio[28851]: info: Shairport-Sync Started Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=debug msg="completed challenge" Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:48 spla-repro go-librespot[29071]: time="2026-09-01T01:53:48+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:48 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:48 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:49 spla-repro sudo[29142]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:49 spla-repro sudo[29142]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:53:49 spla-repro sudo[29142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:49 spla-repro sudo[29142]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:49 spla-repro mpd[29035]: 2026-09-01T01:53:49 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 01:53:49 spla-repro sudo[29144]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:49 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Sep 01 01:53:49 spla-repro sudo[29005]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:49 spla-repro sudo[28994]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:49 spla-repro sudo[29149]: volumio : unable to resolve host spla-repro: System error Sep 01 01:53:49 spla-repro sudo[29144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:53:49 spla-repro sudo[29144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:49 spla-repro sudo[29149]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 01 01:53:49 spla-repro sudo[29144]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:49 spla-repro sudo[29149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:53:49 spla-repro volumio[28851]: info: Completed starting Core Plugins Sep 01 01:53:49 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:49 spla-repro volumio[28851]: info: ----- MyVolumio plugins startup ---- Sep 01 01:53:49 spla-repro volumio[28851]: info: ------------------------------------------- Sep 01 01:53:49 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 01 01:53:49 spla-repro sudo[29149]: pam_unix(sudo:session): session closed for user root Sep 01 01:53:49 spla-repro volumio[28851]: error: MPD error: The expression evaluated to a falsy value: Sep 01 01:53:49 spla-repro volumio[28851]: assert.ok(self.idling) Sep 01 01:53:49 spla-repro volumio[28851]: error: The expression evaluated to a falsy value: Sep 01 01:53:49 spla-repro volumio[28851]: assert.ok(self.idling) Sep 01 01:53:49 spla-repro volumio[28851]: error: updateQueue error: null Sep 01 01:53:49 spla-repro volumio[28851]: info: Upmpdcli Daemon Started Sep 01 01:53:49 spla-repro volumio[28851]: info: MPD running with PID29035 Sep 01 01:53:49 spla-repro volumio[28851]: ,establishing connection Sep 01 01:53:49 spla-repro volumio[28851]: error: updateQueue error: null Sep 01 01:53:50 spla-repro volumio[28851]: info: go-librespot daemon successfully initialized Sep 01 01:53:51 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Sep 01 01:53:51 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:51 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:51 spla-repro go-librespot[29154]: go-librespot daemon starting... Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=debug msg="app state loaded" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=info msg="zeroconf server listening on port 38335" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:51 spla-repro go-librespot[29155]: time="2026-09-01T01:53:51+02:00" level=debug msg="obtained new client token: AAEQ3XJtQ3z7Ifoa/3DJYy1unDhkYEviebuTIfeLtpE2zOSOGerD4ZPX/unGyHsHOFFT3UDW/hoCbwJ6kGZPt0d+HJiqiAgFBBVXndNKzkJYtSbW4uG2RENCWXfBWqmrkyIMBXpOcEbm/NDinLulK8X9XFaOVHpgJNy+eIeQ7mpxZ0Kg2jZuHwwWUdIK7L2DzV5/ORJ7/jipFI1ybmbsrfY6p0EVenWCCZMcC143EU9Qq5EIKFuJHperMg==" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="completed challenge" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=debug msg="completed challenge" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:52 spla-repro go-librespot[29155]: time="2026-09-01T01:53:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:52 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:52 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:52 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:53:52 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:53:52 spla-repro volumio[28851]: info: Listing playlists Sep 01 01:53:52 spla-repro volumio[28851]: info: Listing playlists Sep 01 01:53:53 spla-repro volumio[28851]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:53 spla-repro volumio[28851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:53:54 spla-repro volumio[28851]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Sep 01 01:53:55 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Sep 01 01:53:55 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:56 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:56 spla-repro go-librespot[29165]: go-librespot daemon starting... Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="app state loaded" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=info msg="zeroconf server listening on port 33309" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="obtained new client token: AAHlceMnwCm7qRAn4WcQldbF7g7GtMf8RYMAaYTzhB4Kiqar0GsWMTysLEYoYOTvo0t22muODEJb0aEOrl06BeqiTREaComrJuFwikLbr9XjD9m7UFE7wdJWWmp3VY8BxbGDIWXrGFlLUqgarVTW30sILPkc/cfyTNdwWOCvVj6mcSq70Ls3+PuddtP+tE73YpD5rPOwvAbl/SjaEdlU6jD37ZiFGK2zE8bAEsTcO+ZO5i1tXXVbhmm3zw==" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="completed keyexchange" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="completed challenge" Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:53:56 spla-repro volumio[28851]: info: Initializing connection to go-librespot Websocket Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=debug msg="new websocket client" Sep 01 01:53:56 spla-repro volumio[28851]: info: Connection to go-librespot Websocket established Sep 01 01:53:56 spla-repro go-librespot[29166]: time="2026-09-01T01:53:56+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:53:56 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:53:56 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:53:56 spla-repro volumio[28851]: info: Connection to go-librespot Websocket closed Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin bluetooth to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin multiroom to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin metavolumio to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin cd_controller to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 01 01:53:58 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 01 01:53:59 spla-repro volumio[28851]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 01 01:53:59 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 01 01:53:59 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:59 spla-repro volumio[28851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:53:59 spla-repro volumio[28851]: info: Starting MyVolumio Remote Streaming Endpoints Sep 01 01:53:59 spla-repro volumio[28851]: info: MyVolumio login type: Token Sep 01 01:53:59 spla-repro volumio[28851]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 01 01:53:59 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 01 01:53:59 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Sep 01 01:53:59 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:59 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:53:59 spla-repro go-librespot[29190]: go-librespot daemon starting... Sep 01 01:53:59 spla-repro go-librespot[29191]: time="2026-09-01T01:53:59+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:53:59 spla-repro go-librespot[29191]: time="2026-09-01T01:53:59+02:00" level=debug msg="app state loaded" Sep 01 01:53:59 spla-repro go-librespot[29191]: time="2026-09-01T01:53:59+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:54:00 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 01 01:54:00 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 01 01:54:00 spla-repro volumio[28851]: info: Streaming services startup Sep 01 01:54:00 spla-repro volumio[28851]: info: Starting Streaming Daemon Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=info msg="zeroconf server listening on port 40943" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:00 spla-repro volumio[28851]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 01 01:54:00 spla-repro sudo[29201]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:00 spla-repro sudo[29201]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 01 01:54:00 spla-repro sudo[29201]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:00 spla-repro sudo[29201]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:00 spla-repro volumio[28851]: info: Getting Spotify volume Sep 01 01:54:00 spla-repro volumio[28851]: info: Initializing connection to go-librespot Websocket Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="obtained new client token: AAFlHUBQDmveeKZbKdop+VXpQpNKOuAzM9y4ZoHtZz/8wb567rk3bkMxh2+0R6k8Ihgrk6OY5skXuP/rbGitV7MdFG8paJkKOCJj1c26khbWGcKlfUly3axDZuJdrOkLMypW8TdTkT4zh0H0QmIFhiETYbYFnXDq0bJNh4NbLeDdScTFUUvJpRz48CnaqwPL2aQUUJ0AkETtIPEtW0yzoszmDzi/3x3tyByNHh073xvye5RJOqIewUdBGw==" Sep 01 01:54:00 spla-repro volumio[28851]: error: Cannot start Volumio Streaming Daemon Sep 01 01:54:00 spla-repro volumio[28851]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 01 01:54:00 spla-repro volumio[28851]: sudo: unable to resolve host spla-repro: System error Sep 01 01:54:00 spla-repro volumio[28851]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 01 01:54:00 spla-repro volumio[28851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="new websocket client" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:00 spla-repro volumio[28851]: info: Connection to go-librespot Websocket established Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=debug msg="completed challenge" Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:00 spla-repro volumio[28851]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:00 spla-repro volumio[28851]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:00 spla-repro go-librespot[29191]: time="2026-09-01T01:54:00+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:00 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:00 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:00 spla-repro volumio[28851]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:54:00 spla-repro volumio[28851]: Error: socket hang up Sep 01 01:54:00 spla-repro volumio[28851]: at connResetException (node:internal/errors:720:14) Sep 01 01:54:00 spla-repro volumio[28851]: at Socket.socketOnEnd (node:_http_client:519:23) Sep 01 01:54:00 spla-repro volumio[28851]: at Socket.emit (node:events:526:35) Sep 01 01:54:00 spla-repro volumio[28851]: at endReadableNT (node:internal/streams/readable:1376:12) Sep 01 01:54:00 spla-repro volumio[28851]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Sep 01 01:54:00 spla-repro volumio[28851]: code: 'ECONNRESET', Sep 01 01:54:00 spla-repro volumio[28851]: response: undefined Sep 01 01:54:00 spla-repro volumio[28851]: } Sep 01 01:54:00 spla-repro volumio[28851]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:54:01 spla-repro sudo[29221]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:01 spla-repro sudo[29221]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-01 01:53' Sep 01 01:54:01 spla-repro sudo[29221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:01 spla-repro sudo[29221]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:02 spla-repro volumio[28851]: sudo: unable to resolve host spla-repro: System error Sep 01 01:54:02 spla-repro volumio-remote-updater[725]: [2026-09-01 01:54:02] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Sep 01 01:54:02 spla-repro volumio-remote-updater[725]: [2026-09-01 01:54:02] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Sep 01 01:54:02 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:54:02.066+02:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Sep 01 01:54:02 spla-repro systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:02 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:54:02.077+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:54:02 spla-repro systemd[1]: volumio.service: Failed with result 'exit-code'. Sep 01 01:54:02 spla-repro systemd[1]: volumio.service: Consumed 27.772s CPU time. Sep 01 01:54:02 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:54:02 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:54:02 spla-repro systemd[1]: volumio.service: Scheduled restart job, restart counter is at 15810. Sep 01 01:54:02 spla-repro systemd[1]: Started dynamicswap.service - dynamicswap service. Sep 01 01:54:02 spla-repro systemd[1]: Stopped volumio.service - Volumio Backend Module. Sep 01 01:54:02 spla-repro systemd[1]: volumio.service: Consumed 27.772s CPU time. Sep 01 01:54:02 spla-repro systemd[1]: Started volumio.service - Volumio Backend Module. Sep 01 01:54:02 spla-repro systemd[1]: dynamicswap.service: Deactivated successfully. Sep 01 01:54:03 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:54:03.080+02:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Sep 01 01:54:03 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Sep 01 01:54:03 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:03 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:03 spla-repro go-librespot[29252]: go-librespot daemon starting... Sep 01 01:54:03 spla-repro go-librespot[29253]: time="2026-09-01T01:54:03+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:03 spla-repro go-librespot[29253]: time="2026-09-01T01:54:03+02:00" level=debug msg="app state loaded" Sep 01 01:54:03 spla-repro go-librespot[29253]: time="2026-09-01T01:54:03+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=info msg="zeroconf server listening on port 41623" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="obtained new client token: AAHulQYRznC3AMbuPtksZtOx8iJtrOeuM9cjQIxnqKsyC7hbOeEdlMjRp4RoC8os7olhQXeVlwxG0asZt6KU+kL2fHa5WR+CG9G1bg2bkRyM3TasK2QV5VsWhrjtEyt3A4xEaIfk5h73pAv/5NKuR4fShwuIW8xhPPg2+mKPvJOP4dLMer2AA4iwwqCvUTVfo1OwkNdGHpmOnmEzhY0CKSf0qRa9qWGWbSpaK5pI+fLLQ5JQ2c568eI=" Sep 01 01:54:04 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:04 spla-repro volumio[29237]: info: ----- Volumio3 ---- Sep 01 01:54:04 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:04 spla-repro volumio[29237]: info: ----- System startup ---- Sep 01 01:54:04 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+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" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="connected to ap-gew1.spotify.com:443" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=debug msg="completed challenge" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:04 spla-repro go-librespot[29253]: time="2026-09-01T01:54:04+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:04 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:04 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:05 spla-repro volumio[29237]: info: MYVOLUMIO Environment detected Sep 01 01:54:05 spla-repro volumio[29237]: info: Plugin folders cleanup Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning into folder /volumio/app/plugins/ Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category audio_interface Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category miscellanea Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category music_service Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category plugins.json Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category system_controller Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category user_interface Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning into folder /data/plugins/ Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category audio_interface Sep 01 01:54:05 spla-repro volumio[29237]: info: Scanning category music_service Sep 01 01:54:05 spla-repro volumio[29237]: info: Plugin folders cleanup completed Sep 01 01:54:05 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:05 spla-repro volumio[29237]: info: ----- Core plugins startup ---- Sep 01 01:54:05 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:05 spla-repro volumio[29237]: info: Loading plugins from folder /volumio/app/plugins/ Sep 01 01:54:05 spla-repro volumio[29237]: info: Adding plugin upnp to MyMusic Plugins Sep 01 01:54:05 spla-repro volumio[29237]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 01 01:54:05 spla-repro volumio[29237]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 01 01:54:05 spla-repro volumio[29237]: info: Loading plugins from folder /data/plugins/ Sep 01 01:54:05 spla-repro volumio[29237]: info: Loading plugin "system"... Sep 01 01:54:05 spla-repro volumio[29237]: info: Loading plugin "appearance"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "network"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Refreshing Cached IP Addresses Sep 01 01:54:06 spla-repro sudo[29275]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:06 spla-repro sudo[29277]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:06 spla-repro sudo[29275]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:54:06 spla-repro sudo[29275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:06 spla-repro sudo[29277]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "services"... Sep 01 01:54:06 spla-repro sudo[29277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "volumio5onboarding"... Sep 01 01:54:06 spla-repro sudo[29284]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:06 spla-repro sudo[29275]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:06 spla-repro sudo[29284]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 01 01:54:06 spla-repro sudo[29284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "alsa_controller"... Sep 01 01:54:06 spla-repro sudo[29277]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:06 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "wizard"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "networkfs"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Starting Udev Watcher for removable devices Sep 01 01:54:06 spla-repro volumio[29237]: info: Ignoring mount for partition: boot Sep 01 01:54:06 spla-repro volumio[29237]: info: Ignoring mount for partition: volumio Sep 01 01:54:06 spla-repro volumio[29237]: info: Ignoring mount for partition: volumio_data Sep 01 01:54:06 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "volumio_command_line_client"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "upnp"... Sep 01 01:54:06 spla-repro volumio[29237]: info: [1788220446563] Starting Upmpd Daemon Sep 01 01:54:06 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "my_music"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "mpd"... Sep 01 01:54:06 spla-repro volumio[29237]: info: Loading plugin "upnp_browser"... Sep 01 01:54:07 spla-repro volumio-remote-updater[725]: [2026-09-01 01:54:07] [connect] Successful connection Sep 01 01:54:07 spla-repro sudo[29284]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:07 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Sep 01 01:54:07 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:07 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:07 spla-repro go-librespot[29308]: go-librespot daemon starting... Sep 01 01:54:07 spla-repro go-librespot[29309]: time="2026-09-01T01:54:07+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:07 spla-repro go-librespot[29309]: time="2026-09-01T01:54:07+02:00" level=debug msg="app state loaded" Sep 01 01:54:07 spla-repro go-librespot[29309]: time="2026-09-01T01:54:07+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+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]" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+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]" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=info msg="zeroconf server listening on port 32789" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=debug msg="obtained new client token: AAH30m59rWaFUF3msZdDk4dbHjuMduOiUdpubiFuLajafyEwfwyxYeF2dFcVnccidhH6vQKYoqfwwe++z+3yaoLHB2EOOgZZcBqWCMOxOcqe+qfvVTeLAg7V1eD2RSBD3mZfvFMsqbexZ4R86U6Yntctkzn+heQQYm06dtW7MRA4JQOPpKu7Xma4yti16ultb/Za7df0zqCeJSrk+DyIf7+PJS4WInXYNEibAi3ejwenYj0UikaW8qg=" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=debug msg="completed challenge" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:08 spla-repro go-librespot[29309]: time="2026-09-01T01:54:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:08 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:08 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:08 spla-repro volumio[29237]: info: Starting UPNP Browser Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "alarm-clock"... Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "airplay_emulation"... Sep 01 01:54:08 spla-repro volumio[29237]: info: Starting Shairport Sync Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "last_100"... Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "webradio"... Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "i2s_dacs"... Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "volumiodiscovery"... Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** For more information see Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:54:08 spla-repro volumio[29237]: *** WARNING *** For more information see Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** For more information see Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 01:54:08 spla-repro node[29237]: *** WARNING *** For more information see Sep 01 01:54:08 spla-repro volumio[29237]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 01 01:54:08 spla-repro volumio[29237]: info: Discovery: Started advertising with name: Spálňa-repro Sep 01 01:54:08 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 01:54:08 spla-repro volumio[29237]: info: Loading plugin "spop"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "outputs"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "albumart"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Plugin example_plugin is not enabled Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "inputs"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "updater_comm"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Plugin mpdemulation is not enabled Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "rest_api"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading plugin "websocket"... Sep 01 01:54:10 spla-repro volumio[29237]: info: Starting Socket.io Server version 1.7.4 Sep 01 01:54:10 spla-repro volumio[29237]: info: Plugin fusiondsp is not enabled Sep 01 01:54:10 spla-repro volumio[29237]: info: Loading i18n strings for locale sk Sep 01 01:54:10 spla-repro volumio[29237]: Updating browse sources language Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::initPlayerControls Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: Express server listening on port 3000 Sep 01 01:54:10 spla-repro volumio[29237]: [Metrics] WebUI: 6s 750.69ms Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::resetVolumioState Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::getcurrentVolume Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:54:10 spla-repro volumio[29237]: info: Cannot read play queue from file Sep 01 01:54:10 spla-repro volumio[29237]: info: Volumio Network Manager: Network status updated: 1 Sep 01 01:54:10 spla-repro volumio[29237]: 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 Sep 01 01:54:10 spla-repro volumio[29320]: Forking 3 albumart workers Sep 01 01:54:10 spla-repro volumio[29237]: Unable to parse: Sep 01 01:54:10 spla-repro volumio[29237]: Simple mixer control 'Master',0 Sep 01 01:54:10 spla-repro volumio[29237]: Capabilities: volume volume-joined Sep 01 01:54:10 spla-repro volumio[29237]: Playback channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Capture channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Limits: 0 - 248 Sep 01 01:54:10 spla-repro volumio[29237]: Mono: 112 [45%] Sep 01 01:54:10 spla-repro volumio[29237]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:54:10 spla-repro volumio[29237]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.202 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:10 spla-repro volumio[29237]: verbose: New Socket.io Connection to 192.168.200.203:3000 from 192.168.200.201 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Sep 01 01:54:10 spla-repro volumio[29237]: Unable to parse: Sep 01 01:54:10 spla-repro volumio[29237]: Simple mixer control 'Master',0 Sep 01 01:54:10 spla-repro volumio[29237]: Capabilities: volume volume-joined Sep 01 01:54:10 spla-repro volumio[29237]: Playback channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Capture channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Limits: 0 - 248 Sep 01 01:54:10 spla-repro volumio[29237]: Mono: 112 [45%] Sep 01 01:54:10 spla-repro volumio[29237]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::pushState Sep 01 01:54:10 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::volumioPushState Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::updateTrackBlock Sep 01 01:54:10 spla-repro volumio[29237]: info: CorePlayQueue::getTrackBlock Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::setRepeat null single undefined Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::pushState Sep 01 01:54:10 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::volumioPushState Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::setRandom null Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreStateMachine::pushState Sep 01 01:54:10 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:10 spla-repro volumio[29237]: info: CoreCommandRouter::volumioPushState Sep 01 01:54:10 spla-repro volumio[29237]: info: Setting Device type: Raspberry PI Sep 01 01:54:10 spla-repro volumio-remote-updater[725]: [2026-09-01 01:54:10] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1788220447 101 Sep 01 01:54:10 spla-repro volumio[29237]: 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 Sep 01 01:54:10 spla-repro volumio[29237]: info: Completed loading Core Plugins Sep 01 01:54:10 spla-repro volumio[29237]: info: Preparing to generate the ALSA configuration file Sep 01 01:54:10 spla-repro volumio[29237]: 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 Sep 01 01:54:10 spla-repro volumio[29237]: Unable to parse: Sep 01 01:54:10 spla-repro volumio[29237]: Simple mixer control 'Master',0 Sep 01 01:54:10 spla-repro volumio[29237]: Capabilities: volume volume-joined Sep 01 01:54:10 spla-repro volumio[29237]: Playback channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Capture channels: Mono Sep 01 01:54:10 spla-repro volumio[29237]: Limits: 0 - 248 Sep 01 01:54:10 spla-repro volumio[29237]: Mono: 112 [45%] Sep 01 01:54:10 spla-repro volumio[29237]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: adding d4caa6fc-95c1-41bd-89e0-c640d24940c4 Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: Found device kuchyna-repro Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: Connecting to remote: 192.168.200.201 Sep 01 01:54:11 spla-repro volumio[29237]: 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 Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: adding 284e4a17-0388-4ad0-8157-75a8b67cae8e Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: Found device kupelna-repro Sep 01 01:54:11 spla-repro volumio[29237]: info: Discovery: Connecting to remote: 192.168.200.202 Sep 01 01:54:11 spla-repro volumio[29237]: 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 Sep 01 01:54:11 spla-repro volumio[29237]: Unable to parse: Sep 01 01:54:11 spla-repro volumio[29237]: Simple mixer control 'Master',0 Sep 01 01:54:11 spla-repro volumio[29237]: Capabilities: volume volume-joined Sep 01 01:54:11 spla-repro volumio[29237]: Playback channels: Mono Sep 01 01:54:11 spla-repro volumio[29237]: Capture channels: Mono Sep 01 01:54:11 spla-repro volumio[29237]: Limits: 0 - 248 Sep 01 01:54:11 spla-repro volumio[29237]: Mono: 112 [45%] Sep 01 01:54:11 spla-repro volumio[29237]: info: VolumeController:: Volume=undefined Mute =false Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreStateMachine::pushState Sep 01 01:54:11 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::volumioPushState Sep 01 01:54:11 spla-repro volumio[29237]: info: Asound.conf file unchanged, so no further update is needed Sep 01 01:54:11 spla-repro volumio[29237]: info: Output device has changed, restarting MPD Sep 01 01:54:11 spla-repro volumio[29237]: info: Output device has changed, restarting Shairport Sync Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:11 spla-repro sudo[29377]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:11 spla-repro sudo[29379]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:11 spla-repro volumio[29237]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:54:11 spla-repro volumio[29237]: info: ___________ START PLUGINS ___________ Sep 01 01:54:11 spla-repro sudo[29377]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:54:11 spla-repro sudo[29377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:11 spla-repro sudo[29379]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:54:11 spla-repro sudo[29379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:11 spla-repro sudo[29377]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:11 spla-repro volumio[29237]: info: ControllerMpd::onStart: Initializing MPD Sep 01 01:54:11 spla-repro volumio[29237]: info: Creating MPD Configuration file Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:54:11 spla-repro volumio[29237]: info: [1788220451379] CoreMusicLibrary::Adding element Mediálne servery Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:54:11 spla-repro sudo[29387]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:11 spla-repro sudo[29387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Sep 01 01:54:11 spla-repro sudo[29387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:11 spla-repro systemd[1]: Stopping mpd.service - Music Player Daemon... Sep 01 01:54:11 spla-repro volumio[29237]: info: UPNP Browser: Client initialized successfully Sep 01 01:54:11 spla-repro sudo[29389]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:11 spla-repro sudo[29391]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:11 spla-repro sudo[29391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:11 spla-repro sudo[29391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:11 spla-repro sudo[29387]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:11 spla-repro sudo[29389]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 01:54:11 spla-repro sudo[29389]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:11 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:54:11 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:54:11 spla-repro systemd[1]: mpd.service: Consumed 4.584s CPU time. Sep 01 01:54:11 spla-repro sudo[29389]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:11 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Sep 01 01:54:11 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:54:11 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:54:11 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:54:11 spla-repro volumio[29237]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 01:54:11 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:54:11 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:54:11 spla-repro volumio[29237]: info: [1788220451621] CoreMusicLibrary::Adding element Last_100 Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:54:11 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:11 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:54:11 spla-repro go-librespot[29406]: go-librespot daemon starting... Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 01:54:11 spla-repro volumio[29237]: info: [1788220451667] CoreMusicLibrary::Adding element Webradio Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 01:54:11 spla-repro systemd[1]: mpd.service: Deactivated successfully. Sep 01 01:54:11 spla-repro systemd[1]: Stopped mpd.service - Music Player Daemon. Sep 01 01:54:11 spla-repro go-librespot[29408]: time="2026-09-01T01:54:11+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:11 spla-repro go-librespot[29408]: time="2026-09-01T01:54:11+02:00" level=debug msg="app state loaded" Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:54:11 spla-repro systemd[1]: mpd.socket: Deactivated successfully. Sep 01 01:54:11 spla-repro systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Sep 01 01:54:11 spla-repro systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Sep 01 01:54:11 spla-repro volumio[29237]: info: Initializing BBC Radios Sep 01 01:54:11 spla-repro systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Sep 01 01:54:11 spla-repro systemd[1]: Starting mpd.service - Music Player Daemon... Sep 01 01:54:11 spla-repro go-librespot[29408]: time="2026-09-01T01:54:11+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:11 spla-repro volumio[29237]: info: Creating Spotify config file Sep 01 01:54:11 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:12 spla-repro sudo[29419]: root : unable to resolve host spla-repro: System error Sep 01 01:54:12 spla-repro sudo[29419]: sudo: unable to resolve host spla-repro: System error Sep 01 01:54:12 spla-repro sudo[29419]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 01:54:12 spla-repro sudo[29419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Sep 01 01:54:12 spla-repro sudo[29419]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54: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-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+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]" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+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]" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=info msg="zeroconf server listening on port 33607" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=debug msg="obtained new client token: AAEmKPXUjKsHpSw1Q3Cgy3pm1gvVVFrbnAQqu0/uKpLtElY/IB/1/0y7i9oU8kWDRdr77/skFU9xQ9dq66yYR7vtHnUMRYr+47qWn8tpQfV0jQHOrEqUDwt0fL0m7+nHUhn+crAc8FXunA9FUgqcXiUjeft1NTCFW6N6wvXuyW/WTokLr+JN1gblMeTJWzy39s9Gr1B2uf5n13g1b0f8XpqQizklWeyZFFhaD5ZYQSdNtKXvP6HgDcFKbQ==" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=debug msg="completed challenge" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:12 spla-repro go-librespot[29408]: time="2026-09-01T01:54:12+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:12 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:12 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:12 spla-repro volumio[29237]: info: Volumio Calling Home Sep 01 01:54:13 spla-repro volumio[29339]: Starting albumart workers Sep 01 01:54:13 spla-repro volumio[29338]: Starting albumart workers Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:13 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: adding e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: Found device Spálňa-repro Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:13 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: this is already registered, e4ea6882-b508-4641-a5d5-383d83cd05b4 Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: Found device Spálňa-repro Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:13 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:13 spla-repro volumio[29336]: Starting albumart workers Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: Connected to remote: 192.168.200.201 Sep 01 01:54:13 spla-repro volumio[29237]: info: MPD Permissions set Sep 01 01:54:13 spla-repro volumio[29237]: info: MPD Permissions set Sep 01 01:54:13 spla-repro volumio[29237]: info: Discovery: Connected to remote: 192.168.200.202 Sep 01 01:54:13 spla-repro volumio[29237]: info: Volumio called home Sep 01 01:54:13 spla-repro volumio[29237]: info: Spotify config file written Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Sep 01 01:54:13 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:13 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:13 spla-repro sudo[29438]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:14 spla-repro sudo[29438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 01 01:54:14 spla-repro sudo[29438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:14 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:14 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:14 spla-repro go-librespot[29440]: go-librespot daemon starting... Sep 01 01:54:14 spla-repro sudo[29438]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=debug msg="app state loaded" Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:14 spla-repro volumio[29237]: 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 Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 01:54:14 spla-repro volumio[29237]: info: No need to fix Spotify hosts Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 01 01:54:14 spla-repro volumio[29237]: 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 Sep 01 01:54:14 spla-repro volumio[29237]: info: Received Get System Info Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 01:54:14 spla-repro volumio[29237]: info: Discovery: Getting this device information Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:14 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:14 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=info msg="zeroconf server listening on port 46641" Sep 01 01:54:14 spla-repro go-librespot[29441]: time="2026-09-01T01:54:14+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:15 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:15 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:15 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 01 01:54:15 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=debug msg="obtained new client token: AAFys3oDLXSyWBeJfjVtiCcpi4Kc6dqKKzszU6GCxr2LMCkHGlmakLQDKwAqsfrZCQWMayI6WFv4q2eqZOwONRXyGUAa7QCEe0uFOX78f0h5/EoATF2dpp4kS5rurl6htUiwVUqknp1HbkDeMcIf/gsJ+80YTTE26qav6fUQ9fhyHS2OLUOmtct0RQpqu8i46cu2Drmnpf+DpRmQNwWZ4cValpi47Ff69wMibI9amYod7l4EOEBI0PQ=" Sep 01 01:54:15 spla-repro volumio[29237]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Sep 01 01:54:15 spla-repro volumio[29237]: info: An error occurred while refreshing Spotify Token Error: Bad Request Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:15 spla-repro volumio[29237]: info: Starting Shairport Sync Sep 01 01:54:15 spla-repro volumio[29237]: info: Starting Shairport Sync Sep 01 01:54:15 spla-repro volumio[29237]: info: Starting Shairport Sync Sep 01 01:54:15 spla-repro sudo[29480]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:15 spla-repro sudo[29480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=debug msg="completed challenge" Sep 01 01:54:15 spla-repro sudo[29480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:15 spla-repro sudo[29482]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:15 spla-repro volumio[29237]: info: Listing playlists Sep 01 01:54:15 spla-repro sudo[29482]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:54:15 spla-repro volumio[29237]: info: Listing playlists Sep 01 01:54:15 spla-repro sudo[29482]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:15 spla-repro sudo[29485]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:15 spla-repro sudo[29485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 01:54:15 spla-repro sudo[29485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:15 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:15 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:15 spla-repro systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Sep 01 01:54:15 spla-repro systemd[1]: shairport-sync.service: Deactivated successfully. Sep 01 01:54:15 spla-repro systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:54:15 spla-repro systemd[1]: shairport-sync.service: Consumed 1.904s CPU time. Sep 01 01:54:15 spla-repro go-librespot[29441]: time="2026-09-01T01:54:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:15 spla-repro systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Sep 01 01:54:15 spla-repro sudo[29480]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:15 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:15 spla-repro sudo[29482]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:15 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:15 spla-repro volumio[29237]: info: Shairport-Sync Started Sep 01 01:54:15 spla-repro volumio[29237]: Error adding Membership: Error: addMembership EINVAL Sep 01 01:54:15 spla-repro volumio[29237]: info: Shairport-Sync Started Sep 01 01:54:15 spla-repro sudo[29485]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:15 spla-repro volumio[29237]: info: Shairport-Sync Started Sep 01 01:54:15 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:54:15.890+02:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 01 01:54:16 spla-repro sudo[29518]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:16 spla-repro sudo[29518]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 01:54:16 spla-repro sudo[29518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:16 spla-repro sudo[29518]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:16 spla-repro sudo[29520]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:16 spla-repro sudo[29520]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 01:54:16 spla-repro sudo[29520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:16 spla-repro sudo[29520]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:16 spla-repro sudo[29524]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:16 spla-repro sudo[29524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 01 01:54:16 spla-repro sudo[29524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:16 spla-repro sudo[29524]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:16 spla-repro volumio[29237]: info: Upmpdcli Daemon Started Sep 01 01:54:17 spla-repro mpd[29433]: 2026-09-01T01:54:17 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 01:54:17 spla-repro systemd[1]: Started mpd.service - Music Player Daemon. Sep 01 01:54:17 spla-repro sudo[29391]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:17 spla-repro sudo[29379]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:17 spla-repro volumio[29237]: info: Completed starting Core Plugins Sep 01 01:54:17 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:17 spla-repro volumio[29237]: info: ----- MyVolumio plugins startup ---- Sep 01 01:54:17 spla-repro volumio[29237]: info: ------------------------------------------- Sep 01 01:54:17 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 01 01:54:17 spla-repro volumio[29237]: error: MPD error: The expression evaluated to a falsy value: Sep 01 01:54:17 spla-repro volumio[29237]: assert.ok(self.idling) Sep 01 01:54:17 spla-repro volumio[29237]: error: The expression evaluated to a falsy value: Sep 01 01:54:17 spla-repro volumio[29237]: assert.ok(self.idling) Sep 01 01:54:17 spla-repro volumio[29237]: info: MPD running with PID29433 Sep 01 01:54:17 spla-repro volumio[29237]: ,establishing connection Sep 01 01:54:17 spla-repro volumio[29237]: error: updateQueue error: null Sep 01 01:54:17 spla-repro volumio[29237]: error: updateQueue error: null Sep 01 01:54:17 spla-repro dhcpcd[793]: eth0: failed to renew DHCP, rebinding Sep 01 01:54:17 spla-repro dhcpcd[793]: eth0: leased 192.168.200.203 for 300 seconds Sep 01 01:54:17 spla-repro systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Sep 01 01:54:17 spla-repro systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Sep 01 01:54:17 spla-repro systemd[1]: welcome.service: Deactivated successfully. Sep 01 01:54:17 spla-repro systemd[1]: Stopped welcome.service - Show a welcome message on console. Sep 01 01:54:17 spla-repro systemd[1]: Stopping welcome.service - Show a welcome message on console... Sep 01 01:54:17 spla-repro systemd[1]: Starting welcome.service - Show a welcome message on console... Sep 01 01:54:17 spla-repro welcome[29549]: Resolved ip:[1] 192.168.200.203 Sep 01 01:54:17 spla-repro systemd[1]: Finished welcome.service - Show a welcome message on console. Sep 01 01:54:17 spla-repro systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Sep 01 01:54:17 spla-repro volumio[29237]: info: go-librespot daemon successfully initialized Sep 01 01:54:18 spla-repro volumio[29237]: info: Received Get System Info Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 01:54:18 spla-repro volumio[29237]: info: Discovery: Getting this device information Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:18 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 01 01:54:18 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 01 01:54:18 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Sep 01 01:54:18 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:18 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:18 spla-repro go-librespot[29554]: go-librespot daemon starting... Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=debug msg="app state loaded" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=info msg="zeroconf server listening on port 46013" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:18 spla-repro go-librespot[29555]: time="2026-09-01T01:54:18+02:00" level=debug msg="obtained new client token: AAG4CS+18f4rnhKkueORy6vjJRHbCV6s7NFFOEXDOOYFN2DSb9DfleMGjctjcXOXbLQrON/HRfnTXxX6M4n96gMyj/gJ5wk4GCTR6TE73zC/qBWsTnyebTIPr/4QnxYCxPtM49sLBeqPlQkme6xvTniqwgHfcaPu0uIF65mITy4DHQNDv78Qg3ONijhFLTX8DRfjIXrqB0O3y1m5bs/3Jr4a5VvCuBMkun7mheN3FSmMnflGLj2R6b/pLg==" Sep 01 01:54:19 spla-repro go-librespot[29555]: time="2026-09-01T01:54:19+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:19 spla-repro volumio5-onboarding[4505]: time=2026-09-01T01:54:19.027+02:00 level=INFO msg="service successfully established" component=discovery/localnet Sep 01 01:54:19 spla-repro go-librespot[29555]: time="2026-09-01T01:54:19+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:19 spla-repro go-librespot[29555]: time="2026-09-01T01:54:19+02:00" level=debug msg="completed challenge" Sep 01 01:54:19 spla-repro go-librespot[29555]: time="2026-09-01T01:54:19+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:19 spla-repro go-librespot[29555]: time="2026-09-01T01:54:19+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:19 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:19 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:20 spla-repro volumio[29237]: info: Initializing connection to go-librespot Websocket Sep 01 01:54:21 spla-repro volumio[29237]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:54:22 spla-repro volumio[29237]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Sep 01 01:54:22 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Sep 01 01:54:22 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:22 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:22 spla-repro go-librespot[29564]: go-librespot daemon starting... Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=debug msg="app state loaded" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+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]" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+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]" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=info msg="zeroconf server listening on port 34917" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:22 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:22 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=debug msg="obtained new client token: AAH+ApWAF+qNuJ1OvpnI3zHSheZzxIbUZgj8XoTJrio+yE3ogIvyIGvI2niPlcoPlroZwXvdL/AtnV0HMHs5s6+c6sTZwFFJeTS19jZjezgsM9Yo22MOwMeoiBXLbiaBqR32fI8AIpR0JpWSj30pAi3u5IGH3Hi7u3RMGb422GvTNNrFF0pieVNBmeLHn8AQ1Q21MjtFZgalT3NZgOXYHBDB+mi20T4pJng4CvqKKpVh0sftUU2Ez26P2Q==" Sep 01 01:54:22 spla-repro go-librespot[29565]: time="2026-09-01T01:54:22+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:23 spla-repro go-librespot[29565]: time="2026-09-01T01:54:23+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:23 spla-repro go-librespot[29565]: time="2026-09-01T01:54:23+02:00" level=debug msg="completed challenge" Sep 01 01:54:23 spla-repro go-librespot[29565]: time="2026-09-01T01:54:23+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:23 spla-repro go-librespot[29565]: time="2026-09-01T01:54:23+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:23 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:23 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:24 spla-repro volumio[29237]: info: Initializing connection to go-librespot Websocket Sep 01 01:54:24 spla-repro volumio[29237]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin bluetooth to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin multiroom to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin metavolumio to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin cd_controller to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin qobuzconnect to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin smart_inputs to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: Adding plugin tidalconnect to MyMusic Plugins Sep 01 01:54:25 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Sep 01 01:54:26 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Sep 01 01:54:26 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:26 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:26 spla-repro go-librespot[29574]: go-librespot daemon starting... Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="app state loaded" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:26 spla-repro volumio[29237]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Sep 01 01:54:26 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Sep 01 01:54:26 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:26 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:26 spla-repro volumio[29237]: info: Starting MyVolumio Remote Streaming Endpoints Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+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]" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+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]" Sep 01 01:54:26 spla-repro volumio[29237]: info: MyVolumio login type: Token Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=info msg="zeroconf server listening on port 42635" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:26 spla-repro volumio[29237]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Sep 01 01:54:26 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="obtained new client token: AAF2+1Aus0y9BiP/JQWlSVz1fCyptxLsu9kXV0xLET6Os7ZJCA6M43a/jZzpz/tv1czh/PdbpflhlhJ+HYdfqA4jPdNV3auaL1c5tZExn2GH6QNdfoXhddIZYSN++Q8v/Hb8fdlpVTiBAVDdNKeU0KAwcl1BGFGL1yBvW0Kw4nIrZDDC3jIYz5Mws3dYxmtMYnC1aCD7l6E7qoHBBrkQIgebpY0jZkWT0dogtZqD+w7ExA/+KDGD4j97vg==" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=debug msg="completed challenge" Sep 01 01:54:26 spla-repro go-librespot[29575]: time="2026-09-01T01:54:26+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:27 spla-repro go-librespot[29575]: time="2026-09-01T01:54:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:27 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:27 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:27 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Sep 01 01:54:27 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Sep 01 01:54:27 spla-repro volumio[29237]: info: Streaming services startup Sep 01 01:54:27 spla-repro volumio[29237]: info: Starting Streaming Daemon Sep 01 01:54:27 spla-repro sudo[29600]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:27 spla-repro volumio[29237]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Sep 01 01:54:27 spla-repro sudo[29600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 01 01:54:27 spla-repro sudo[29600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:27 spla-repro sudo[29600]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:27 spla-repro volumio[29237]: info: Initializing connection to go-librespot Websocket Sep 01 01:54:27 spla-repro volumio[29237]: error: Cannot start Volumio Streaming Daemon Sep 01 01:54:27 spla-repro volumio[29237]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 01 01:54:27 spla-repro volumio[29237]: sudo: unable to resolve host spla-repro: System error Sep 01 01:54:27 spla-repro volumio[29237]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 01 01:54:27 spla-repro volumio[29237]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:54:28 spla-repro volumio[29237]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Sep 01 01:54:28 spla-repro volumio[29237]: info: MyVolumio token set successfully Sep 01 01:54:28 spla-repro volumio[29237]: info: MYVOLUMIO: Adding device Sep 01 01:54:28 spla-repro volumio[29237]: info: MYVOLUMIO: Evaluating Server Sep 01 01:54:29 spla-repro volumio[29237]: info: MyVolumio status changed Sep 01 01:54:29 spla-repro volumio[29237]: info: Streaming services startup Sep 01 01:54:29 spla-repro volumio[29237]: info: Starting Streaming Daemon Sep 01 01:54:29 spla-repro volumio[29237]: info: Removing browser output: myVolumio user plan is not superstar Sep 01 01:54:29 spla-repro volumio[29237]: info: Removing audio output: Sep 01 01:54:29 spla-repro volumio[29237]: info: Stoppping Tunnel 1 Sep 01 01:54:29 spla-repro sudo[29627]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:29 spla-repro sudo[29627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Sep 01 01:54:29 spla-repro sudo[29627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:29 spla-repro sudo[29627]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:29 spla-repro sudo[29630]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:29 spla-repro sudo[29630]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Sep 01 01:54:29 spla-repro sudo[29630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:29 spla-repro volumio[29237]: error: Cannot start Volumio Streaming Daemon Sep 01 01:54:29 spla-repro volumio[29237]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Sep 01 01:54:29 spla-repro volumio[29237]: sudo: unable to resolve host spla-repro: System error Sep 01 01:54:29 spla-repro volumio[29237]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 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. Sep 01 01:54:29 spla-repro sudo[29630]: pam_unix(sudo:session): session closed for user root Sep 01 01:54:29 spla-repro volumio[29237]: info: Remote SSH Stopped Sep 01 01:54:29 spla-repro volumio[29237]: info: Setting Geolocation for MyVolumio to eu6 Sep 01 01:54:29 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:29 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:29 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:29 spla-repro volumio[29237]: info: Successfully Added MyVolumio device Sep 01 01:54:30 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Sep 01 01:54:30 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:30 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:30 spla-repro go-librespot[29632]: go-librespot daemon starting... Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="app state loaded" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:30 spla-repro volumio[29237]: info: Updating MyVolumio device info Sep 01 01:54:30 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:30 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:30 spla-repro volumio[29237]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+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]" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+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]" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=info msg="zeroconf server listening on port 41637" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="obtained new client token: AAFJbAYEFBSCdzRbngPQBZL4VZUarGycZOfVMLXx9wWz7kqVS03XKiO/Tg1IArFbQJIyjbIJfOiJnDGX1rHb+zOu6bUMxK1ZR1jHa+CzADiaFvmAwMi2SLA7gRupaX3ZdQdVlqZ9GuGMj7kJtIFNo+Xghs72yam+hkIuRyleL6Q9apAj70ZVIYpS9/EQ3chTzr/kjx73jRyPQtI11UO3mGHNU5VFSPOrQidMoknzFjg0FHK5RsOZX9aS0Q==" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="completed challenge" Sep 01 01:54:30 spla-repro volumio[29237]: info: Successfully Updated MyVolumio device Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:30 spla-repro volumio[29237]: info: Initializing connection to go-librespot Websocket Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=debug msg="new websocket client" Sep 01 01:54:30 spla-repro volumio[29237]: info: Connection to go-librespot Websocket established Sep 01 01:54:30 spla-repro go-librespot[29633]: time="2026-09-01T01:54:30+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:30 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:30 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 01:54:30 spla-repro volumio[29237]: info: Connection to go-librespot Websocket closed Sep 01 01:54:32 spla-repro volumio[29237]: info: CoreCommandRouter::volumioGetState Sep 01 01:54:32 spla-repro volumio[29237]: info: CorePlayQueue::getTrack 0 Sep 01 01:54:32 spla-repro volumio[29237]: info: Listing playlists Sep 01 01:54:32 spla-repro volumio[29237]: info: Listing playlists Sep 01 01:54:33 spla-repro volumio[29237]: info: Getting Spotify volume Sep 01 01:54:33 spla-repro volumio[29237]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:54:33 spla-repro volumio[29237]: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 01 01:54:33 spla-repro volumio[29237]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Sep 01 01:54:33 spla-repro volumio[29237]: errno: -111, Sep 01 01:54:33 spla-repro volumio[29237]: code: 'ECONNREFUSED', Sep 01 01:54:33 spla-repro volumio[29237]: syscall: 'connect', Sep 01 01:54:33 spla-repro volumio[29237]: address: '127.0.0.1', Sep 01 01:54:33 spla-repro volumio[29237]: port: 9879, Sep 01 01:54:33 spla-repro volumio[29237]: response: undefined Sep 01 01:54:33 spla-repro volumio[29237]: } Sep 01 01:54:33 spla-repro volumio[29237]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 01:54:33 spla-repro systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Sep 01 01:54:33 spla-repro systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:34 spla-repro systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Sep 01 01:54:34 spla-repro go-librespot[29654]: go-librespot daemon starting... Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=info msg="running go-librespot 0.7.1" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=debug msg="app state loaded" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+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]" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+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]" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+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]" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=info msg="zeroconf server listening on port 33527" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=debug msg="obtained new client token: AAEO8ak33rr7BjJzmUw7xqlkAjHJ6ftVFhDz0M77CcK0Nea/LYMNSco1Ga5Hec1fx+LyTlcLsovsDklMYFOZUOouTJFf7+ccvz4BiiM6Rj49Fn0l7uU7ATGE05k+2QeIHOyb5ngwhitZ0FcJQBnd1fJLXqnvx5VgVznswlNwgax9BtOy6aDg43Bg+aWyJPB2piQMLcQouZYm/KNSUIBJjSa0NnaiC76Kdw9ZNh34QISRyqEhqb8kTa5LDw==" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=debug msg="completed keyexchange" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=debug msg="completed challenge" Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=info msg="authenticated AP" username="4b*********************lb" Sep 01 01:54:34 spla-repro sudo[29668]: volumio : unable to resolve host spla-repro: System error Sep 01 01:54:34 spla-repro sudo[29668]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-09-01 01:53' Sep 01 01:54:34 spla-repro sudo[29668]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Sep 01 01:54:34 spla-repro go-librespot[29656]: time="2026-09-01T01:54:34+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Sep 01 01:54:34 spla-repro systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 01 01:54:34 spla-repro systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"